wait_for_completion_timeout problem ???

wait_for_completion_timeout problem ???

[Eli Cohen]

Hi,
	
I have a problem with using this function. I am referring to
drivers/infiniband/hw/mthca/mthca_cmd.c line 394. For convenience I
quote from this code:

	init_completion(&context->done);

	err = mthca_cmd_post(dev, in_param,
			     out_param ? *out_param : 0,
			     in_modifier, op_modifier,
			     op, context->token, 1);
	if (err)
		goto out;

	if (!wait_for_completion_timeout(&context->done, timeout)) {
		err = -EBUSY;
		goto out;
	}

timeout is 10 * HZ. Sometimes this function returns 0 which signifies
timeout. However I can see that the interrupt handler called
complete(&context->done)
around 200 usec after calling wait_for_completion_timout(). When the
function returns I can see that context->done.done equals 1 which
confirms that complete was indeed called. Looking at the implementation
of wait_for_completion_timout() it appears that complete() did not
succeed to wake the process sleeping. But the timer callback function in
schedule_timeout() did manage to wake up the sleeping process. Do you
have any idea if there are any known circumstances that can lead to this
behaviour. Any idea how to debug this?

Thanks
Eli

Re: wait_for_completion_timeout problem ???

[Dmitry Adamushko]

Hi,

>
> I have a problem with using this function. I am referring to
> drivers/infiniband/hw/mthca/mthca_cmd.c line 394. For convenience I
> quote from this code:
>
>         init_completion(&context->done);
>
>         err = mthca_cmd_post(dev, in_param,
>                              out_param ? *out_param : 0,
>                              in_modifier, op_modifier,
>                              op, context->token, 1);
>         if (err)
>                 goto out;
>
>         if (!wait_for_completion_timeout(&context->done, timeout)) {
>                 err = -EBUSY;
>                 goto out;
>         }
>
> timeout is 10 * HZ. Sometimes this function returns 0 which signifies
> timeout. However I can see that the interrupt handler called
> complete(&context->done)
> around 200 usec after calling wait_for_completion_timout(). When the
> function returns I can see that context->done.done equals 1 which
> confirms that complete was indeed called.

The sequence of events can be as follows:

a caller gets blocked in wait_for_completion_timeout() on
schedule_timeout() which literally means:

   i ) will be unblocked (scheduled back) after "timeout" has expired;

   ii) will be unblocked by someone calling wake_up_*(&x->wait);

(wait_for_completion_timeout() inserted our caller into "x->wait" wait queue)

in both cases schedule_timeout() will do

...
        schedule(); <------------------ here we get CPU back
        del_singleshot_timer_sync(&timer);
        timeout = expire - jiffies;

 out:
        return timeout < 0 ? 0 : timeout;

"expire" is when (+latency) we were expected to be woken up by a
timeer -> timeout.

Now the point is that our waiter could have been "waken up" (become
"ready" from the point of view of the scheduler) earlier but it was
just "scheduled" (got CPU back) later than "expire" so that's why the
return value is 0 (timeout < 0 ==> return 0).

IOW, schedule_timeout() indicates whether a process has been scheduled
back /earlier than timeout/ (so return value >0) or /later/ (0).

It doesn't indicate why the process has been woked up ( i.e. (i) or
(ii) above ).

In you case it became /runnable/ because of complete() but it got
scheuled later than /timeout/.

And wait_for_completion_timeout() takes it as a /timeout condition/.

So either all the users of wait_for_completion_timeout() should
additionally check for x->done after they got scheduled

or

wait_for_completion_timeout() should return something different that
encodes the fact /event happened/ and not just /event happened _and_ a
caller has got scheduled back earlier than timeout.



>
> Thanks
> Eli

-- 
Best regards,
Dmitry Adamushko

Re: wait_for_completion_timeout problem ???

[Eli Cohen]

On Thu, 2007-03-01 at 15:28 +0100, Dmitry Adamushko wrote:
> Hi,
> 
> >
> > I have a problem with using this function. I am referring to
> > drivers/infiniband/hw/mthca/mthca_cmd.c line 394. For convenience I
> > quote from this code:
> >
> >         init_completion(&context->done);
> >
> >         err = mthca_cmd_post(dev, in_param,
> >                              out_param ? *out_param : 0,
> >                              in_modifier, op_modifier,
> >                              op, context->token, 1);
> >         if (err)
> >                 goto out;
> >
> >         if (!wait_for_completion_timeout(&context->done, timeout)) {
> >                 err = -EBUSY;
> >                 goto out;
> >         }
> >
> > timeout is 10 * HZ. Sometimes this function returns 0 which signifies
> > timeout. However I can see that the interrupt handler called
> > complete(&context->done)
> > around 200 usec after calling wait_for_completion_timout(). When the
> > function returns I can see that context->done.done equals 1 which
> > confirms that complete was indeed called.
> 
> The sequence of events can be as follows:
> 
> a caller gets blocked in wait_for_completion_timeout() on
> schedule_timeout() which literally means:
> 
>    i ) will be unblocked (scheduled back) after "timeout" has expired;
> 
>    ii) will be unblocked by someone calling wake_up_*(&x->wait);
> 
> (wait_for_completion_timeout() inserted our caller into "x->wait" wait queue)
> 
> in both cases schedule_timeout() will do
> 
> ...
>         schedule(); <------------------ here we get CPU back
>         del_singleshot_timer_sync(&timer);
>         timeout = expire - jiffies;
> 
>  out:
>         return timeout < 0 ? 0 : timeout;
> 
> "expire" is when (+latency) we were expected to be woken up by a
> timeer -> timeout.
> 
> Now the point is that our waiter could have been "waken up" (become
> "ready" from the point of view of the scheduler) earlier but it was
> just "scheduled" (got CPU back) later than "expire" so that's why the
> return value is 0 (timeout < 0 ==> return 0).
> 
> IOW, schedule_timeout() indicates whether a process has been scheduled
> back /earlier than timeout/ (so return value >0) or /later/ (0).
> 
> It doesn't indicate why the process has been woked up ( i.e. (i) or
> (ii) above ).
> 
> In you case it became /runnable/ because of complete() but it got
> scheuled later than /timeout/.
> 
> And wait_for_completion_timeout() takes it as a /timeout condition/.
> 
> So either all the users of wait_for_completion_timeout() should
> additionally check for x->done after they got scheduled
There is only one process waiting on the completion object.
> 
> or
> 
> wait_for_completion_timeout() should return something different that
> encodes the fact /event happened/ and not just /event happened _and_ a
> caller has got scheduled back earlier than timeout.
That possibility crossed my mind but I ruled it out since the the
timeout is 10 sec while completion arrived less then 4 msec after
calling wait_for_completion_timeout(). So it appears to me unlikely that
it will the task will be in the run list but will not get CPU time for
nearly 10 seconds. I will give it a try though. I will increase timeout
to 20 sec.

> 
> 
> 
> >
> > Thanks
> > Eli
> 

Re: wait_for_completion_timeout problem ???

[Dmitry Adamushko]

On 01/03/07, Eli Cohen <eli@mellanox.co.il> wrote:
> >...
> > wait_for_completion_timeout() should return something different that
> > encodes the fact /event happened/ and not just /event happened _and_ a
> > caller has got scheduled back earlier than timeout.
> That possibility crossed my mind but I ruled it out since the the
> timeout is 10 sec while completion arrived less then 4 msec after
> calling wait_for_completion_timeout(). So it appears to me unlikely that
> it will the task will be in the run list but will not get CPU time for
> nearly 10 seconds. I will give it a try though. I will increase timeout
> to 20 sec.
>

Mea culpa. Don't know why I took it as 10 ms.. Yep, in case of seconds
it rather becomes a mere theoretical possibility.

Are you sure there are no other "waiters" being blocked on the same
"completion" at the same time? complete_all()?

Anyway, do "cat /proc/your_task_pid/status" and look at the "State: "
field. It should be "R" in case wake_up_*() was called for this task.


-- 
Best regards,
Dmitry Adamushko

Re: wait_for_completion_timeout problem ???

[Eli Cohen]

On Thu, 2007-03-01 at 16:14 +0100, Dmitry Adamushko wrote:

> Mea culpa. Don't know why I took it as 10 ms.. Yep, in case of seconds
> it rather becomes a mere theoretical possibility.
> 
> Are you sure there are no other "waiters" being blocked on the same
> "completion" at the same time? complete_all()?
> 
> Anyway, do "cat /proc/your_task_pid/status" and look at the "State: "
> field. It should be "R" in case wake_up_*() was called for this task.
> 

Thanks for your good advices. Right now it seems that increasing the
timeout to 60 sec did the trick :-)
The test I was running has many threads and maybe there is starvation of
tasks. The system is also not too responsive to say the least.

Re: wait_for_completion_timeout problem ???

[Eli Cohen]

On Thu, 2007-03-01 at 15:28 +0100, Dmitry Adamushko wrote:

> So either all the users of wait_for_completion_timeout() should
> additionally check for x->done after they got scheduled
> 
> or
> 
> wait_for_completion_timeout() should return something different that
> encodes the fact /event happened/ and not just /event happened _and_ a
> caller has got scheduled back earlier than timeout.
> 

The second suggestion makes sense to me more and is more portable then
the first one.