[linux-cifs-client] Re: huge variation in wait_event called by wait_for_response. Potential bug? Help please

[wasrshi nimara]

Hi,

Figured this one out. That was a bad question!

What i should have said:

Is it ok to replace the wait_event with wait_event_timeout. Looks like the
denotify thread
periodically wakes up and cleans this queue. So the wait time is always
delta 0 - 15 seconds.

I am working on an app that needs strict guarantees on this timeout, hence
the question.

thanks
warshi



On Wed, Nov 12, 2008 at 3:30 PM, wasrshi nimara <warshinimara at gmail.com>wrote:

> Hi,
>
> I was trying to time the wait_for_response since i noticed huge variations
> in observerd timeouts. I was
> playing around with the timeout values but did not see any changing in the
> use land for write call
> blocking time. I set the STD_OP timeout to 5000 msec.
>
>
> Looks like the way wait event is called with the time_after as a condition
> option is leading to some
> bug. Couldnt find the cause yet ...
>
> But the measured timeouts are 200% above expected values.
>
> Replacing wait_event with wait_event_timeout fixed this problem and
> observed timeout is
> as expected.
>
> I have cut and pasted the changes made to this function and the observed
> results.
>
> CHANGES:
>
>         curr_timeout = timeout + jiffies;
>         j1 = jiffies;
>         cFYI(1,("States are midq %d and tcpStatus %d\n", midQ->midState,
> ses->server->tcpStatus));
>         cFYI(1, ("timeout %lu, jiffies %lu, curr_timeout %lu\n", timeout,
> jiffies, curr_timeout));
>
> wait_event(ses->server->response_q,
>
>             (!(midQ->midState == MID_REQUEST_SUBMITTED))
> ||
>             time_after(jiffies, curr_timeout) ||
>             ((ses->server->tcpStatus != CifsGood)
> &&
>              (ses->server->tcpStatus !=
> CifsNew)));
>         j2=jiffies;
>
>         cFYI(1,("waited for %lu with HZ as %lu\n", (j2-j1),
> HZ));
>
>         j1 = jiffies;
>         wait_event_timeout(ses->server->response_q,
>             (!(midQ->midState == MID_REQUEST_SUBMITTED)) ||
>             ((ses->server->tcpStatus != CifsGood) &&
>              (ses->server->tcpStatus != CifsNew)),
> timeout);
>
>         j2 =
> jiffies;
>
>         cFYI(1,("waited for %lu with HZ as %lu\n", (j2-j1), HZ));
>
>
>
> LOGS:
>
> Nov 12 23:03:50 10 vmunix:  fs/cifs_2_6_24_3/file.c: Setting write to std
> op in cifs_writepages
> Nov 12 23:03:50 10 vmunix:
> Nov 12 23:03:50 10 vmunix:  fs/cifs_2_6_24_3/cifssmb.c: write2 at 0 49152
> bytes
> Nov 12 23:03:50 10 vmunix:  fs/cifs_2_6_24_3/transport.c: For smb_command
> 47
> Nov 12 23:03:50 10 vmunix:  fs/cifs_2_6_24_3/transport.c: Sending smb:
> total_len 49220
> Nov 12 23:03:50 10 vmunix:  fs/cifs_2_6_24_3/transport.c: SendReceive2:Ret
> code is 0
> Nov 12 23:03:50 10 vmunix:
> Nov 12 23:03:50 10 vmunix:  fs/cifs_2_6_24_3/transport.c: Wait times are
> 5000 timeout and 3000 time_to_wait
> Nov 12 23:03:50 10 vmunix:
> Nov 12 23:03:50 10 vmunix:  fs/cifs_2_6_24_3/transport.c: States are midq 2
> and tcpStatus 1
> Nov 12 23:03:50 10 vmunix:
> Nov 12 23:03:50 10 vmunix:  fs/cifs_2_6_24_3/transport.c: timeout 5000,
> jiffies 97199, curr_timeout 102199
> Nov 12 23:03:50 10 vmunix:
> Nov 12 23:04:01 10 vmunix:  fs/cifs_2_6_24_3/transport.c: waited for 10635
> with HZ as 1000    <------------------------- timeout took 10635 msec with
> wait_event instead of 5000 msec.
> Nov 12 23:04:01 10 vmunix:
> Nov 12 23:04:06 10 vmunix:  fs/cifs_2_6_24_3/transport.c: waited for 5000
> with HZ as 1000 <----------------------------- as expected.
> Nov 12 23:04:06 10 vmunix:
> Nov 12 23:04:06 10 vmunix:  fs/cifs_2_6_24_3/transport.c:  112834, 73500
> time after jiffies aye
>
>
-------------- next part --------------
HTML attachment scrubbed and removed