* Re: [pnfs] pnfs first write has very long delay
[not found] <AANLkTi=XSSM5+wmCrVzQrZF8rA81OLqDO_dMzUqwHc7g@mail.gmail.com>
@ 2010-10-21 16:48 ` Benny Halevy
2010-10-21 17:08 ` William A. (Andy) Adamson
0 siblings, 1 reply; 2+ messages in thread
From: Benny Halevy @ 2010-10-21 16:48 UTC (permalink / raw)
To: quanli gui; +Cc: linux-pnfs
On 2010-10-21 14:03, quanli gui wrote:
> When pnfs is mount on the client, I write a file to the mount dir by the
> first time. It must wait a very long time until the pnfs complete the write.
> When the operation waited, I dmesg the operation information. Find that
> NFS: 0 initiated write call (req 0:13/200809, 3035 bytes @ offset 49152)
> --> nfs4_setup_sequence clp c450a800 session c450ac00 sr_slotid 128
> --> nfs41_setup_sequence
> --> nfs4_find_slot used_slots=0007 highest_used=2 max_slots=16
> <-- nfs4_find_slot used_slots=000f highest_used=3 slotid=3
> <-- nfs41_setup_sequence slotid=3 seqid=1
> <-- nfs4_setup_sequence status=0
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=1 slotid=3 max_slotid=3
> cache_this=1
> filelayout_write_call_done new off 40960 orig offset 40960
> pnfs_writeback_done: Begin (status -10008)
What kind of DS are you using?
The 10008 error means that the DS returned NFS4ERR_DELAY
so we need to understand why that happened.
Benny
> put_lseg: lseg ce417e40 ref 3 valid 1
> NFS: 34 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> pnfs_writepages End (trypnfs:0)
> filelayout_write_call_done new off 49152 orig offset 49152
> pnfs_writeback_done: Begin (status -10008)
> put_lseg: lseg ce417e40 ref 2 valid 1
> NFS: 35 nfs_writeback_done (status -10008 count 3035)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> nfs4_renew_state: start
> nfs4_renew_state: failed to call renewd. Reason: lease not expired
> nfs4_renew_state: requeueing work. Lease period = 56
> nfs4_renew_state: done
> nfs4_renew_state: start
> nfs4_renew_state: failed to call renewd. Reason: lease not expired
> nfs4_renew_state: requeueing work. Lease period = 56
> nfs4_renew_state: done
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=2 slotid=0 max_slotid=3
> cache_this=1
> NFS: 29 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=2 slotid=0 max_slotid=2
> cache_this=1
> NFS: 30 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=2 slotid=1 max_slotid=3
> cache_this=1
> NFS: 31 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=2 slotid=1 max_slotid=2
> cache_this=1
> NFS: 32 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=2 slotid=2 max_slotid=3
> cache_this=1
> NFS: 33 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=2 slotid=2 max_slotid=2
> cache_this=1
> NFS: 34 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=2 slotid=3 max_slotid=3
> cache_this=1
> NFS: 35 nfs_writeback_done (status -10008 count 3035)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> nfs4_renew_state: start
> nfs4_renew_state: failed to call renewd. Reason: lease not expired
> nfs4_renew_state: requeueing work. Lease period = 37
> nfs4_renew_state: done
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=3 slotid=0 max_slotid=3
> cache_this=1
> NFS: 29 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=3 slotid=0 max_slotid=2
> cache_this=1
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=3 slotid=1 max_slotid=3
> cache_this=1
> NFS: 30 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> NFS: 31 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=3 slotid=1 max_slotid=2
> cache_this=1
> NFS: 32 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=3 slotid=2 max_slotid=3
> cache_this=1
> NFS: 33 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=3 slotid=2 max_slotid=2
> cache_this=1
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=3 slotid=3 max_slotid=3
> cache_this=1
> NFS: 34 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> NFS: 35 nfs_writeback_done (status -10008 count 3035)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=4 slotid=0 max_slotid=3
> cache_this=1
> NFS: 29 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=4 slotid=0 max_slotid=2
> cache_this=1
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=4 slotid=1 max_slotid=3
> cache_this=1
> NFS: 30 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> NFS: 31 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=4 slotid=1 max_slotid=2
> cache_this=1
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=4 slotid=2 max_slotid=3
> cache_this=1
> NFS: 32 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> NFS: 33 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> encode_compound: tag=
> encode_sequence: sessionid=1287677253:2:2:0 seqid=4 slotid=3 max_slotid=3
> cache_this=1
> encode_compound: tag=
> encode_sequence: sessionid=1287677247:2:2:0 seqid=4 slotid=2 max_slotid=2
> cache_this=1
> NFS: 35 nfs_writeback_done (status -10008 count 3035)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> NFS: 34 nfs_writeback_done (status -10008 count 8192)
> pnfs4_write_done DS write
> <-- pnfs4_write_done status= -11
> I don't know why so many pnfs_write_done() return -11 only for the first
> write. But after the first write, I write files again. This time the time of
> the operation is OK. Please tell me why this thing happen.
>
^ permalink raw reply [flat|nested] 2+ messages in thread
* Re: [pnfs] pnfs first write has very long delay
2010-10-21 16:48 ` [pnfs] pnfs first write has very long delay Benny Halevy
@ 2010-10-21 17:08 ` William A. (Andy) Adamson
0 siblings, 0 replies; 2+ messages in thread
From: William A. (Andy) Adamson @ 2010-10-21 17:08 UTC (permalink / raw)
To: Benny Halevy; +Cc: quanli gui, linux-pnfs
The first I/O to a data server includes:
1) setting up the session EXCHANGE_ID, CREATE_SESSION
2) the first time a Linux server (including a data server ) sees a
file handle, it does an upcall to mountd to import the share
information into the kernel. This is one cause of the NFS4_ERR_DELAY.
The write status of -11 is EAGAIN which is the response to NFS4_ERR_DELAY
-->Andy
On Thu, Oct 21, 2010 at 12:48 PM, Benny Halevy <bhalevy@panasas.com> wrote:
> On 2010-10-21 14:03, quanli gui wrote:
>> When pnfs is mount on the client, I write a file to the mount dir by the
>> first time. It must wait a very long time until the pnfs complete the write.
>> When the operation waited, I dmesg the operation information. Find that
>> NFS: 0 initiated write call (req 0:13/200809, 3035 bytes @ offset 49152)
>> --> nfs4_setup_sequence clp c450a800 session c450ac00 sr_slotid 128
>> --> nfs41_setup_sequence
>> --> nfs4_find_slot used_slots=0007 highest_used=2 max_slots=16
>> <-- nfs4_find_slot used_slots=000f highest_used=3 slotid=3
>> <-- nfs41_setup_sequence slotid=3 seqid=1
>> <-- nfs4_setup_sequence status=0
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=1 slotid=3 max_slotid=3
>> cache_this=1
>> filelayout_write_call_done new off 40960 orig offset 40960
>> pnfs_writeback_done: Begin (status -10008)
>
> What kind of DS are you using?
> The 10008 error means that the DS returned NFS4ERR_DELAY
> so we need to understand why that happened.
>
> Benny
>
>> put_lseg: lseg ce417e40 ref 3 valid 1
>> NFS: 34 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> pnfs_writepages End (trypnfs:0)
>> filelayout_write_call_done new off 49152 orig offset 49152
>> pnfs_writeback_done: Begin (status -10008)
>> put_lseg: lseg ce417e40 ref 2 valid 1
>> NFS: 35 nfs_writeback_done (status -10008 count 3035)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> nfs4_renew_state: start
>> nfs4_renew_state: failed to call renewd. Reason: lease not expired
>> nfs4_renew_state: requeueing work. Lease period = 56
>> nfs4_renew_state: done
>> nfs4_renew_state: start
>> nfs4_renew_state: failed to call renewd. Reason: lease not expired
>> nfs4_renew_state: requeueing work. Lease period = 56
>> nfs4_renew_state: done
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=2 slotid=0 max_slotid=3
>> cache_this=1
>> NFS: 29 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=2 slotid=0 max_slotid=2
>> cache_this=1
>> NFS: 30 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=2 slotid=1 max_slotid=3
>> cache_this=1
>> NFS: 31 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=2 slotid=1 max_slotid=2
>> cache_this=1
>> NFS: 32 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=2 slotid=2 max_slotid=3
>> cache_this=1
>> NFS: 33 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=2 slotid=2 max_slotid=2
>> cache_this=1
>> NFS: 34 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=2 slotid=3 max_slotid=3
>> cache_this=1
>> NFS: 35 nfs_writeback_done (status -10008 count 3035)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> nfs4_renew_state: start
>> nfs4_renew_state: failed to call renewd. Reason: lease not expired
>> nfs4_renew_state: requeueing work. Lease period = 37
>> nfs4_renew_state: done
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=3 slotid=0 max_slotid=3
>> cache_this=1
>> NFS: 29 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=3 slotid=0 max_slotid=2
>> cache_this=1
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=3 slotid=1 max_slotid=3
>> cache_this=1
>> NFS: 30 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> NFS: 31 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=3 slotid=1 max_slotid=2
>> cache_this=1
>> NFS: 32 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=3 slotid=2 max_slotid=3
>> cache_this=1
>> NFS: 33 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=3 slotid=2 max_slotid=2
>> cache_this=1
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=3 slotid=3 max_slotid=3
>> cache_this=1
>> NFS: 34 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> NFS: 35 nfs_writeback_done (status -10008 count 3035)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=4 slotid=0 max_slotid=3
>> cache_this=1
>> NFS: 29 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=4 slotid=0 max_slotid=2
>> cache_this=1
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=4 slotid=1 max_slotid=3
>> cache_this=1
>> NFS: 30 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> NFS: 31 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=4 slotid=1 max_slotid=2
>> cache_this=1
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=4 slotid=2 max_slotid=3
>> cache_this=1
>> NFS: 32 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> NFS: 33 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677253:2:2:0 seqid=4 slotid=3 max_slotid=3
>> cache_this=1
>> encode_compound: tag=
>> encode_sequence: sessionid=1287677247:2:2:0 seqid=4 slotid=2 max_slotid=2
>> cache_this=1
>> NFS: 35 nfs_writeback_done (status -10008 count 3035)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> NFS: 34 nfs_writeback_done (status -10008 count 8192)
>> pnfs4_write_done DS write
>> <-- pnfs4_write_done status= -11
>> I don't know why so many pnfs_write_done() return -11 only for the first
>> write. But after the first write, I write files again. This time the time of
>> the operation is OK. Please tell me why this thing happen.
>>
> --
> 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
>
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2010-10-21 17:08 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <AANLkTi=XSSM5+wmCrVzQrZF8rA81OLqDO_dMzUqwHc7g@mail.gmail.com>
2010-10-21 16:48 ` [pnfs] pnfs first write has very long delay Benny Halevy
2010-10-21 17:08 ` William A. (Andy) Adamson
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox