* 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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.