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

[wasrshi nimara]

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