pNFS timeouts

pNFS timeouts

[Lukas Hejtmanek]

Hi,

I'm playing with pNFS (spnfs layouts) using one MDS and one DS. I have
a client that mount pNFS volume.=20

I can touch (create) files on that volume immediately:
time touch c

real    0m0.005s
user    0m0.000s
sys     0m0.000s

But creating files with a content suffers from approx. 15 secs timeout:

dd if=3D/dev/zero of=3Dtestf10 bs=3D1M count=3D1=20
1+0 records in
1+0 records out
1048576 bytes (1.0 MB) copied, 15.1156 s, 69.4 kB/s

overwriting the same file works OK:

dd if=3D/dev/zero of=3Dtestf10 bs=3D1M count=3D1
1+0 records in
1+0 records out
1048576 bytes (1.0 MB) copied, 0.0258294 s, 40.6 MB/s

I think this is an interesting part of the debug logs:
[69615.791232] pnfs_writeback_done: Begin (status -10008)
[69615.791238] put_lseg: lseg ffff88003b987840 ref 7 valid 1
[69615.794450] NFS:  6195 nfs_writeback_done (status -10008 count 8192)
[69615.794450] pnfs4_write_done DS write
[69615.794450] nfs41_sequence_done: Error 0 free the slot=20
[69615.794450] nfs4_free_slot: free_slotid 0 highest_used_slotid 5
[69615.794450] <-- pnfs4_write_done status=3D -11
[69615.990137] filelayout_write_call_done new off 8192 orig offset 8192

Any ideas?=20

--=20
Luk=E1=B9 Hejtm=E1nek

Re: pNFS timeouts

[Benny Halevy]

On Jun. 14, 2010, 4:51 -0400, Lukas Hejtmanek <xhejtman@ics.muni.cz> wrote:
> Hi,
> 
> I'm playing with pNFS (spnfs layouts) using one MDS and one DS. I have
> a client that mount pNFS volume. 
> 
> I can touch (create) files on that volume immediately:
> time touch c
> 
> real    0m0.005s
> user    0m0.000s
> sys     0m0.000s
> 
> But creating files with a content suffers from approx. 15 secs timeout:
> 
> dd if=/dev/zero of=testf10 bs=1M count=1 
> 1+0 records in
> 1+0 records out
> 1048576 bytes (1.0 MB) copied, 15.1156 s, 69.4 kB/s
> 
> overwriting the same file works OK:
> 
> dd if=/dev/zero of=testf10 bs=1M count=1
> 1+0 records in
> 1+0 records out
> 1048576 bytes (1.0 MB) copied, 0.0258294 s, 40.6 MB/s
> 
> I think this is an interesting part of the debug logs:
> [69615.791232] pnfs_writeback_done: Begin (status -10008)

I'm not sure if that explains the 15 seconds delay.
I wonder if it could be related to the nfsv4 grace period.
Does this happen if you wait for a couple minutes after
the server restarts before starting the test?

Benny

> [69615.791238] put_lseg: lseg ffff88003b987840 ref 7 valid 1
> [69615.794450] NFS:  6195 nfs_writeback_done (status -10008 count 8192)
> [69615.794450] pnfs4_write_done DS write
> [69615.794450] nfs41_sequence_done: Error 0 free the slot 
> [69615.794450] nfs4_free_slot: free_slotid 0 highest_used_slotid 5
> [69615.794450] <-- pnfs4_write_done status= -11
> [69615.990137] filelayout_write_call_done new off 8192 orig offset 8192
> 
> Any ideas? 
> 

Re: pNFS timeouts

[Lukas Hejtmanek]

Hi,

On Mon, Jun 14, 2010 at 10:11:30AM -0400, Benny Halevy wrote:
> I'm not sure if that explains the 15 seconds delay.
> I wonder if it could be related to the nfsv4 grace period.
> Does this happen if you wait for a couple minutes after
> the server restarts before starting the test?

I repeated the test after approx. 6 hours the server was restarted and =
it is
the same, the delay still happens.=20

But it could be something related, it complains about lease renewal:

Jun 14 16:17:00 undomiel1 kernel: [187434.936220] nfs4_renew_state: don=
e
Jun 14 16:17:00 undomiel1 kernel: [187434.936492] nfs41_sequence_done: =
Error 0 free the slot
Jun 14 16:17:00 undomiel1 kernel: [187434.936500] nfs4_free_slot: free_=
slotid 0 highest_used_slotid -1
Jun 14 16:17:00 undomiel1 kernel: [187434.936507] nfs41_sequence_call_d=
one rpc_cred ffff88003d7a0300
Jun 14 16:17:00 undomiel1 kernel: [187434.936514] <-- nfs41_sequence_ca=
ll_done
Jun 14 16:17:00 undomiel1 kernel: [187434.936522] nfs4_schedule_state_r=
enewal: requeueing work. Lease period =3D 60
Jun 14 16:17:00 undomiel1 kernel: [187434.936530] --> nfs_put_client({2=
})
Jun 14 16:17:16 undomiel1 kernel: [187450.536014] nfs4_renew_state: sta=
rt
Jun 14 16:17:16 undomiel1 kernel: [187450.536045] nfs4_renew_state: fai=
led to call renewd. Reason: lease not expired
Jun 14 16:17:16 undomiel1 kernel: [187450.536056] nfs4_schedule_state_r=
enewal: requeueing work. Lease period =3D 38

The full log can be found at:
http://undomiel.ics.muni.cz/tmp/nfs-log.txt

--=20
Luk=E1=B9 Hejtm=E1nek

Re: pNFS timeouts

[Benny Halevy]

On Jun. 14, 2010, 10:23 -0400, Lukas Hejtmanek <xhejtman@ics.muni.cz> wrote:
> Hi,
> 
> On Mon, Jun 14, 2010 at 10:11:30AM -0400, Benny Halevy wrote:
>> I'm not sure if that explains the 15 seconds delay.
>> I wonder if it could be related to the nfsv4 grace period.
>> Does this happen if you wait for a couple minutes after
>> the server restarts before starting the test?
> 
> I repeated the test after approx. 6 hours the server was restarted and it is
> the same, the delay still happens. 
> 
> But it could be something related, it complains about lease renewal:
> 
> Jun 14 16:17:00 undomiel1 kernel: [187434.936220] nfs4_renew_state: done
> Jun 14 16:17:00 undomiel1 kernel: [187434.936492] nfs41_sequence_done: Error 0 free the slot
> Jun 14 16:17:00 undomiel1 kernel: [187434.936500] nfs4_free_slot: free_slotid 0 highest_used_slotid -1
> Jun 14 16:17:00 undomiel1 kernel: [187434.936507] nfs41_sequence_call_done rpc_cred ffff88003d7a0300
> Jun 14 16:17:00 undomiel1 kernel: [187434.936514] <-- nfs41_sequence_call_done
> Jun 14 16:17:00 undomiel1 kernel: [187434.936522] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> Jun 14 16:17:00 undomiel1 kernel: [187434.936530] --> nfs_put_client({2})
> Jun 14 16:17:16 undomiel1 kernel: [187450.536014] nfs4_renew_state: start
> Jun 14 16:17:16 undomiel1 kernel: [187450.536045] nfs4_renew_state: failed to call renewd. Reason: lease not expired
> Jun 14 16:17:16 undomiel1 kernel: [187450.536056] nfs4_schedule_state_renewal: requeueing work. Lease period = 38

This looks like a complaint but it's actually saying that the "failure"
is due to the fact that everything is OK (lease not expired)

BTW, is this the same issue that Jiri reported?
http://marc.info/?l=linux-nfs&m=127619696004097&w=2

Benny

> 
> The full log can be found at:
> http://undomiel.ics.muni.cz/tmp/nfs-log.txt
> 

Re: pNFS timeouts

[Benny Halevy]

On Jun. 14, 2010, 10:46 -0400, Benny Halevy <bhalevy@panasas.com> wrote:
> On Jun. 14, 2010, 10:23 -0400, Lukas Hejtmanek <xhejtman@ics.muni.cz> wrote:
>> Hi,
>>
>> On Mon, Jun 14, 2010 at 10:11:30AM -0400, Benny Halevy wrote:
>>> I'm not sure if that explains the 15 seconds delay.
>>> I wonder if it could be related to the nfsv4 grace period.
>>> Does this happen if you wait for a couple minutes after
>>> the server restarts before starting the test?
>>
>> I repeated the test after approx. 6 hours the server was restarted and it is
>> the same, the delay still happens. 
>>
>> But it could be something related, it complains about lease renewal:
>>
>> Jun 14 16:17:00 undomiel1 kernel: [187434.936220] nfs4_renew_state: done
>> Jun 14 16:17:00 undomiel1 kernel: [187434.936492] nfs41_sequence_done: Error 0 free the slot
>> Jun 14 16:17:00 undomiel1 kernel: [187434.936500] nfs4_free_slot: free_slotid 0 highest_used_slotid -1
>> Jun 14 16:17:00 undomiel1 kernel: [187434.936507] nfs41_sequence_call_done rpc_cred ffff88003d7a0300
>> Jun 14 16:17:00 undomiel1 kernel: [187434.936514] <-- nfs41_sequence_call_done
>> Jun 14 16:17:00 undomiel1 kernel: [187434.936522] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
>> Jun 14 16:17:00 undomiel1 kernel: [187434.936530] --> nfs_put_client({2})
>> Jun 14 16:17:16 undomiel1 kernel: [187450.536014] nfs4_renew_state: start
>> Jun 14 16:17:16 undomiel1 kernel: [187450.536045] nfs4_renew_state: failed to call renewd. Reason: lease not expired
>> Jun 14 16:17:16 undomiel1 kernel: [187450.536056] nfs4_schedule_state_renewal: requeueing work. Lease period = 38
> 
> This looks like a complaint but it's actually saying that the "failure"
> is due to the fact that everything is OK (lease not expired)
> 
> BTW, is this the same issue that Jiri reported?
> http://marc.info/?l=linux-nfs&m=127619696004097&w=2

looking at http://charon.styxx.cz/tmp/pnfs/pnfs_write_log.txt
There seem to 15 seconds form after getting an NFS4ERR_DELAY
from a DS write to the respective commit.

[69615.596004] --> _pnfs_try_to_write_data
[69615.596004] _pnfs_try_to_write_data: Utilizing pNFS I/O
[69615.596004] pnfs_writepages: Writing ino:3898308 8192@40960
[69615.596004] get_lock_alloc_layout Begin
[69615.596004] get_lock_alloc_layout Return ffff88003b058338
[69615.596004] pnfs_has_layout:Begin
[69615.596004] pnfs_has_layout:Return lseg ffff88003b987840 take_ref 1 ref 7 valid 1
[69615.596004] pnfs_update_layout: Using cached lseg ffff88003b987840 for 8192@40960 iomode 2)
[69615.596004] pnfs_update_layout end (err:0) state 0x0 lseg ffff88003b987840
[69615.596004] pnfs_writepages: Calling layout driver (how 0) write with 2 pages
[69615.596004] --> filelayout_write_pagelist ino 3898308 nr_pages 2 pgbase 0 req 8192@40960 sync 0
[69615.596004] nfs4_pnfs_dserver_get: offset=40960, count=8192, si=0, dsi=0, stripe_count=1, stripe_unit=8192 first_stripe_index 0
[69615.596004] nfs4_pnfs_dserver_get: dev_id=00000351 00000001, ip:port=147.251.11.45.8.1, ds_idx=0 stripe_idx=0, offset=40960, count=8192
[69615.596004] filelayout_write_pagelist ino 3898308 8192@40960 DS:93fb0b2d:2049 147.251.11.45.8.1
[69615.596004] --> pnfs4_proc_write_setup ds_nfs_client ffff88003b98f800
[69615.596004] NFS:     0 initiated write call (req 0:10/3898308, 8192 bytes @ offset 40960)
[69615.596004] --> nfs4_setup_sequence clp ffff88003b98f800 session ffff88003cd8bc00 sr_slotid 128
[69615.596004] --> nfs41_setup_sequence
[69615.596004] --> nfs4_find_slot used_slots=001f highest_used=4 max_slots=16
[69615.596004] <-- nfs4_find_slot used_slots=003f highest_used=5 slotid=5 
[69615.596004] <-- nfs41_setup_sequence slotid=5 seqid=5
[69615.596004] <-- nfs4_setup_sequence status=0
[69615.596004] encode_compound: tag=
[69615.596004] encode_sequence: sessionid=1276181646:3:3:0 seqid=5 slotid=5 max_slotid=5 cache_this=1
[69615.596004] pnfs_writepages End (trypnfs:0)
[69615.791232] pnfs_writeback_done: Begin (status -10008)
[69615.791238] put_lseg: lseg ffff88003b987840 ref 7 valid 1
[69615.794450] NFS:  6195 nfs_writeback_done (status -10008 count 8192)
[69615.794450] pnfs4_write_done DS write
[69615.794450] nfs41_sequence_done: Error 0 free the slot 
[69615.794450] nfs4_free_slot: free_slotid 0 highest_used_slotid 5
[69615.794450] <-- pnfs4_write_done status= -11
...
[69616.196974] pnfs_update_last_write: Wrote 8192@40960 bpos 0, epos: 49151
[69616.196979] pnfs_need_layoutcommit: has_layout=1 ctx=ffff88003b987640
[69616.196983] nfs_writeback_done DS write
[69616.196992] NFS:  6197 write (0:10/3898308 4096@16384) marked for commit
[69616.197000] NFS:  6197 write (0:10/3898308 4096@20480) marked for commit
[69616.197008] NFS:  6198 write (0:10/3898308 4096@24576) marked for commit
[69616.197015] NFS:  6198 write (0:10/3898308 4096@28672) marked for commit
[69616.197022] NFS:  6199 write (0:10/3898308 4096@32768) marked for commit
[69616.197029] NFS:  6199 write (0:10/3898308 4096@36864) marked for commit
[69616.197037] NFS:  6200 write (0:10/3898308 4096@40960) marked for commit
[69616.197044] NFS:  6200 write (0:10/3898308 4096@45056) marked for commit
[69616.197069] filelayout_write_call_done new off 49152 orig offset 49152
[69616.197078] pnfs_writeback_done: Begin (status 8192)
...
[69630.789213] _pnfs_try_to_commit: Utilizing pNFS I/O
[69630.789220] pnfs_commit: Begin
[69630.789226] get_lock_alloc_layout Begin
[69630.789241] get_lock_alloc_layout Return ffff88003b058338
[69630.789245] pnfs_has_layout:Begin
[69630.789249] pnfs_has_layout:Return lseg ffff88003b987840 take_ref 1 ref 2 valid 1
[69630.789254] pnfs_update_layout: Using cached lseg ffff88003b987840 for 189@0 iomode 2)
[69630.789260] pnfs_update_layout end (err:0) state 0x0 lseg ffff88003b987840
[69630.789264] pnfs_commit: Calling layout driver commit
[69630.789270] filelayout_commit data ffff88003cfe7a80 pnfs_client (null) nfslay ffff88003b987880 sync 1
[69630.789276] filelayout_commit stripesize 8192
[69630.789281] nfs4_pnfs_dserver_get: offset=0, count=4096, si=0, dsi=0, stripe_count=1, stripe_unit=8192 first_stripe_index 0
[69630.789289] nfs4_pnfs_dserver_get: dev_id=00000351 00000001, ip:port=147.251.11.45.8.1, ds_idx=0 stripe_idx=0, offset=0, count=4096
[69630.789297] filelayout_commit: Initiating commit: 78013@0 USE DS:
[69630.789301]         ip_addr 93fb0b2d
[69630.789305]         port 2049
[69630.789308]         client ffff88003b98f800
[69630.789311]         ref count 1
[69630.789314]         cl_exchange_flags 60001
[69630.789317]         ip:port 147.251.11.45.8.1
[69630.789322] --> pnfs4_proc_commit_setup ds_nfs_client ffff88003b98f800 commit_through_mds 0
[69630.789327] NFS:     0 initiated commit call
[69630.789341] --> nfs4_setup_sequence clp ffff88003b98f800 session ffff88003cd8bc00 sr_slotid 128
[69630.789347] --> nfs41_setup_sequence
[69630.789355] --> nfs4_find_slot used_slots=0000 highest_used=-1 max_slots=16
[69630.789365] <-- nfs4_find_slot used_slots=0001 highest_used=0 slotid=0 
[69630.789370] <-- nfs41_setup_sequence slotid=0 seqid=23
[69630.789374] <-- nfs4_setup_sequence status=0
[69630.789378] encode_compound: tag=
[69630.789382] encode_sequence: sessionid=1276181646:3:3:0 seqid=23 slotid=0 max_slotid=0 cache_this=1
[69630.789403] pnfs_commit End (trypnfs:0)
[69630.790916] pnfs_commit_done: Begin (status 0)
[69630.790924] put_lseg: lseg ffff88003b987840 ref 2 valid 1
[69630.790929] NFS:  6205 nfs_commit_done (status 0)
[69630.790935] --> pnfs4_commit_done task->tk_status 0
[69630.790940] pnfs4_commit_done DS commit
[69630.790944] nfs41_sequence_done: Error 0 free the slot 
[69630.790958] nfs4_free_slot: free_slotid 0 highest_used_slotid -1
[69630.790966] <-- pnfs4_commit_done
[69630.790975] NFS:       commit (0:10/3898308 4096@0) OK
[69630.790982] NFS:       commit (0:10/3898308 4096@4096) OK
[69630.790988] NFS:       commit (0:10/3898308 4096@8192) OK
[69630.790993] NFS:       commit (0:10/3898308 4096@12288) OK
[69630.790999] NFS:       commit (0:10/3898308 4096@16384) OK
[69630.791005] NFS:       commit (0:10/3898308 4096@20480) OK
[69630.791010] NFS:       commit (0:10/3898308 4096@24576) OK
[69630.791016] NFS:       commit (0:10/3898308 4096@28672) OK
[69630.791021] NFS:       commit (0:10/3898308 4096@32768) OK
[69630.791027] NFS:       commit (0:10/3898308 4096@36864) OK
[69630.791033] NFS:       commit (0:10/3898308 4096@40960) OK
[69630.791042] NFS:       commit (0:10/3898308 4096@45056) OK
[69630.791052] NFS:       commit (0:10/3898308 4096@49152) OK
[69630.791058] NFS:       commit (0:10/3898308 4096@53248) OK
[69630.791064] NFS:       commit (0:10/3898308 4096@57344) OK
[69630.791069] NFS:       commit (0:10/3898308 4096@61440) OK
[69630.791075] NFS:       commit (0:10/3898308 4096@65536) OK
[69630.791080] NFS:       commit (0:10/3898308 4096@69632) OK
[69630.791086] NFS:       commit (0:10/3898308 4096@73728) OK
[69630.791091] NFS:       commit (0:10/3898308 189@77824) OK


> 
> Benny
> 
>>
>> The full log can be found at:
>> http://undomiel.ics.muni.cz/tmp/nfs-log.txt
>>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: pNFS timeouts

[Lukas Hejtmanek]

On Mon, Jun 14, 2010 at 10:46:55AM -0400, Benny Halevy wrote:
> > Jun 14 16:17:00 undomiel1 kernel: [187434.936507] nfs41_sequence_ca=
ll_done rpc_cred ffff88003d7a0300
> > Jun 14 16:17:00 undomiel1 kernel: [187434.936514] <-- nfs41_sequenc=
e_call_done
> > Jun 14 16:17:00 undomiel1 kernel: [187434.936522] nfs4_schedule_sta=
te_renewal: requeueing work. Lease period =3D 60
> > Jun 14 16:17:00 undomiel1 kernel: [187434.936530] --> nfs_put_clien=
t({2})
> > Jun 14 16:17:16 undomiel1 kernel: [187450.536014] nfs4_renew_state:=
 start
> > Jun 14 16:17:16 undomiel1 kernel: [187450.536045] nfs4_renew_state:=
 failed to call renewd. Reason: lease not expired
> > Jun 14 16:17:16 undomiel1 kernel: [187450.536056] nfs4_schedule_sta=
te_renewal: requeueing work. Lease period =3D 38
>=20
> This looks like a complaint but it's actually saying that the "failur=
e"
> is due to the fact that everything is OK (lease not expired)

the state renewal actually starts after 16 seconds after schedule start
renewal for some reason. The nfs_put_client actually starts the renewal=
?

> BTW, is this the same issue that Jiri reported?
> http://marc.info/?l=3Dlinux-nfs&m=3D127619696004097&w=3D2

Yes, but I didn't see any response to that, so I guess his report is no=
t clear
enough.

--=20
Luk=E1=B9 Hejtm=E1nek

Re: pNFS timeouts

[Benny Halevy]

On Jun. 14, 2010, 11:05 -0400, Lukas Hejtmanek <xhejtman@ics.muni.cz> wrote:
> On Mon, Jun 14, 2010 at 10:46:55AM -0400, Benny Halevy wrote:
>>> Jun 14 16:17:00 undomiel1 kernel: [187434.936507] nfs41_sequence_call_done rpc_cred ffff88003d7a0300
>>> Jun 14 16:17:00 undomiel1 kernel: [187434.936514] <-- nfs41_sequence_call_done
>>> Jun 14 16:17:00 undomiel1 kernel: [187434.936522] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
>>> Jun 14 16:17:00 undomiel1 kernel: [187434.936530] --> nfs_put_client({2})
>>> Jun 14 16:17:16 undomiel1 kernel: [187450.536014] nfs4_renew_state: start
>>> Jun 14 16:17:16 undomiel1 kernel: [187450.536045] nfs4_renew_state: failed to call renewd. Reason: lease not expired
>>> Jun 14 16:17:16 undomiel1 kernel: [187450.536056] nfs4_schedule_state_renewal: requeueing work. Lease period = 38
>>
>> This looks like a complaint but it's actually saying that the "failure"
>> is due to the fact that everything is OK (lease not expired)
> 
> the state renewal actually starts after 16 seconds after schedule start
> renewal for some reason. The nfs_put_client actually starts the renewal?
> 

No, the state renewal is done independently in the background.

>> BTW, is this the same issue that Jiri reported?
>> http://marc.info/?l=linux-nfs&m=127619696004097&w=2
> 
> Yes, but I didn't see any response to that, so I guess his report is not clear
> enough.
> 

Re: pNFS timeouts

[Lukas Hejtmanek]

On Mon, Jun 14, 2010 at 11:02:40AM -0400, Benny Halevy wrote:
> looking at http://charon.styxx.cz/tmp/pnfs/pnfs_write_log.txt
> There seem to 15 seconds form after getting an NFS4ERR_DELAY
> from a DS write to the respective commit.

this debug is not applicable to DS?

echo 32767 > /proc/sys/sunrpc/nfs_debug

I can provide debug output from DS, but this does not seem to produce a=
ny
debug output.

--=20
Luk=E1=B9 Hejtm=E1nek