[LTP] [PATCH] lsmod01: parse a copy of /proc/modules

[Stanislav Kholmanskikh]

Recovering an old thread. Please, see below:

On 08/29/2016 06:49 PM, Jan Stancek wrote:
> 
> 
> 
> ----- Original Message -----
>> From: "Stanislav Kholmanskikh" <stanislav.kholmanskikh@oracle.com>
>> To: "Jan Stancek" <jstancek@redhat.com>
>> Cc: "vasily isaenko" <vasily.isaenko@oracle.com>, ltp@lists.linux.it
>> Sent: Monday, 29 August, 2016 4:03:44 PM
>> Subject: Re: [LTP] [PATCH] lsmod01: parse a copy of /proc/modules
>>
>>
>>
>> On 08/29/2016 05:00 PM, Stanislav Kholmanskikh wrote:
>>>
>>>
>>> On 08/29/2016 04:34 PM, Jan Stancek wrote:
>>>>
>>>>
>>>>
>>>>
>>>> ----- Original Message -----
>>>>> From: "Stanislav Kholmanskikh" <stanislav.kholmanskikh@oracle.com>
>>>>> To: "Cyril Hrubis" <chrubis@suse.cz>
>>>>> Cc: "vasily isaenko" <vasily.isaenko@oracle.com>, ltp@lists.linux.it
>>>>> Sent: Monday, 29 August, 2016 3:05:11 PM
>>>>> Subject: Re: [LTP] [PATCH] lsmod01: parse a copy of /proc/modules
>>>>>
>>>>>
>>>>>
>>>>> On 08/29/2016 03:50 PM, Cyril Hrubis wrote:
>>>>>> Hi!
>>>>>>> In my environment, if TMPDIR is on NFSv4, this test case fails with:
>>>>>>>
>>>>>>> lsmod01 1 TFAIL : lsmod output different from /proc/modules.
>>>>>>>   21c21
>>>>>>>   < sunrpc 207591 28
>>>>>>>   ---
>>>>>>>   > sunrpc 207591 29
>>>>>>>
>>>>>>> To avoid such problems I separate the process of getting data from
>>>>>>> /proc/modules and the process of parsing it in the pipe structure.
>>>>>>
>>>>>> So the sunrpc module gets its ref counter incremented from somewhere of
>>>>>> the nfs kernel code once we open file on NFS?
>>>>>
>>>>> Looks so. I hava a share mounted from localhost:
>>>>>
>>>>> [root@skholman-m7 mnt]# mount|grep mnt
>>>>> 127.0.0.1:/opt on /mnt type nfs
>>>>> (rw,vers=4,addr=127.0.0.1,clientaddr=127.0.0.1)
>>>>> [root@skholman-m7 mnt]# awk '{print $1, $2, $3}' /proc/modules|sort >
>>>>> /tmp/not_nfs
>>>>> [root@skholman-m7 mnt]# awk '{print $1, $2, $3}' /proc/modules|sort > nfs
>>>>> [root@skholman-m7 mnt]# grep sunrpc nfs
>>>>> sunrpc 207591 29
>>>>> [root@skholman-m7 mnt]# grep sunrpc /tmp/not_nfs
>>>>> sunrpc 207591 28
>>>>> [root@skholman-m7 mnt]#
>>>>
>>>> And if you do that with just "cat /proc/modules", then there's no
>>>> difference?
>>>> Could it be that it's actually first write that takes extra ref?
>>>> cat is reading in 65536 byte chunks for me, awk only 1024.
>>>
>>> Yes, there is no difference if I use "cat /proc/modules":
>>>
>>> [root@skholman-m7 mnt]# awk '{print $1, $2, $3}' /proc/modules|sort > nfs
>>> [root@skholman-m7 mnt]# grep sunrpc nfs
>>> sunrpc 207591 29
>>> [root@skholman-m7 mnt]# cat /proc/modules > temp
>>> [root@skholman-m7 mnt]# awk '{print $1, $2, $3}' temp|sort > nfs
>>> [root@skholman-m7 mnt]# grep sunrpc temp
>>> sunrpc 207591 28 nfs,nfsd,lockd,nfs_acl,auth_rpcgss, Live
>>> 0x00000000101ec000
>>> [root@skholman-m7 mnt]#
>>>
>>> As for 1024. lsmod also reads /proc/modules in 1024 bytes chunks.
>>
>> I suppose it's something related to using the pipe construction, since
>> this change also "fixes" the issue:
> 
> I'm suspecting this to be some kind of race between opening file on
> nfs and reading /proc/modules at the same time:
> 
> # sh -c "cat /proc/modules | cat > temp2"; grep sunrpc temp2
> sunrpc 300464 31 nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,auth_rpcgss,nfs_acl,lockd, Live 0xffffffffa03a4000
> 
> # taskset -c 0 sh -c "cat /proc/modules | cat > temp2"; grep sunrpc temp2
> sunrpc 300464 30 nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,auth_rpcgss,nfs_acl,lockd, Live 0xffffffffa03a4000
> 
> or
> 
> # dd if=/proc/modules bs=1 | cat > temp2; grep sunrpc temp2
> 6332+0 records in
> 6332+0 records out
> 6332 bytes (6.3 kB) copied, 0.00288249 s, 2.2 MB/s
> sunrpc 300464 30 nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,auth_rpcgss,nfs_acl,lockd, Live 0xffffffffa03a4000
> 
> # dd if=/proc/modules bs=2 | cat > temp2; grep sunrpc temp2
> 3166+0 records in
> 3166+0 records out
> 6332 bytes (6.3 kB) copied, 0.00148174 s, 4.3 MB/s
> sunrpc 300464 31 nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,auth_rpcgss,nfs_acl,lockd, Live 0xffffffffa03a4000
> 
> or
> 
> # cat /proc/modules | sh -c cat > temp2; grep sunrpc temp2
> sunrpc 300464 31 nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,auth_rpcgss,nfs_acl,lockd, Live 0xffffffffa03a4000
> 
> # cat /proc/modules | sh -c "cat > temp2"; grep sunrpc temp2
> sunrpc 300464 30 nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,auth_rpcgss,nfs_acl,lockd, Live 0xffffffffa03a4000
> 

Tried this all again.

This is from a 4.1-based kernel in a VirtualBox host:

[root@ol6-x64 mnt]# mount|grep mnt
127.0.0.1:/opt/ on /mnt type nfs (rw,vers=3,addr=127.0.0.1)
[root@ol6-x64 mnt]# grep sunrpc /proc/modules
sunrpc 329262 28
nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,lockd,nfs_acl,auth_rpcgss, Live
0xffffffffa0366000
[root@ol6-x64 mnt]# dd if=/dev/zero of=file bs=512

While the above dd command is running, in a separate shell I see:

[stas@ol6-x64 ~]$ lsmod|grep sunrpc
sunrpc                329262  36
nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,lockd,nfs_acl,auth_rpcgss
[stas@ol6-x64 ~]$

[root@ol6-x64 mnt]# grep sunrpc /proc/modules
sunrpc 329262 28
nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,lockd,nfs_acl,auth_rpcgss, Live
0xffffffffa0366000
[root@ol6-x64 mnt]# dd if=/proc/modules bs=1 | cat > temp2; grep sunrpc
temp2
2564+0 records in
2564+0 records out
2564 bytes (2.6 kB) copied, 0.00313203 s, 819 kB/s
sunrpc 329262 29
nfsv3,rpcsec_gss_krb5,nfsv4,nfs,nfsd,lockd,nfs_acl,auth_rpcgss, Live
0xffffffffa0366000
[root@ol6-x64 mnt]#

The same situation is with NFSv4.

So it turns out that writing to a file on NFS increases the sunrpc
module reference counter. I don't observe this with ext4.ko.

So I find that my original patch is fine, it just needs a proper
description.

Thoughts?