Re: multi-second application stall in open()

[Vivek Goyal <vgoyal@redhat.com>]

On Mon, Jun 25, 2012 at 11:22:32AM -0500, Josh Hunt wrote:
> On Mon, Jun 25, 2012 at 8:30 AM, Vivek Goyal <vgoyal@redhat.com> wrote:
> > On Fri, Jun 22, 2012 at 04:34:07PM -0500, Josh Hunt wrote:
> >
> > [..]
> >> Shouldn't the queue stay on the RR list until it is empty?
> >
> > This does look odd. cfqq should stay on service tree as long as it has
> > requests.
> >
> > Can you attach the full log again. Also make sure that blktrace is not
> > dropping any trace events.
> >
> > In slice_expire() we check following.
> >
> >        if (cfq_cfqq_on_rr(cfqq) && RB_EMPTY_ROOT(&cfqq->sort_list))
> >                cfq_del_cfqq_rr(cfqd, cfqq);
> >
> > So for some reason RB_EMPTY_ROOT() is returning true. But we must have
> > added the request and it should not have been empty.
> >
> > cfq_insert_request()
> >  cfq_add_rq_rb()
> >    elv_rb_add()
> >
> > So may be little more tracing after request addition will help. Just check
> > that RB_EMPTY_ROOT() is not true after addition of request and also print
> > number of requests queued.
> >
> > In slice_expired() we can probably put a BUG_ON() which checks following.
> >
> > BUG_ON(RB_EMPTY_ROOT(&cfqq->sort_list) && (cfqq->queued[0] || cfqq->queued[1]));
> >
> > Thanks
> > Vivek
> 
> Vivek
> 
> First off thanks for all the time you've spent helping me on this :)
> 
> I'm attaching the log. I will add more instrumentation based on your
> mail and let you know the results.

I suspect that cfq5917 are actually two queues. One sync and other async.
In latest kernels, trace messages append "A" or "S" in queue name to
represent async/sync queue. Why do I think so.

- I see that cfq5917 has dispatched both "W" and "R" requests. "R" don't
  get queued in sync queues and vice a versa.

- Once cfq5917 has preempted cfq5917. A queue can't preempt itself. 

  8,0    1   296615  4847.030318652  5917  I   R 1572951 + 8 (    2793)
[syslogd]
  8,0    1        0  4847.030321446     0  m   N cfq5917 insert_request
  8,0    1        0  4847.030323122     0  m   N cfq5917 add_to_rr
  8,0    1        0  4847.030325636     0  m   N cfq5917 preempt
  8,0    1        0  4847.030327033     0  m   N cfq5917 slice expired t=1
  8,0    1        0  4847.030328710     0  m   N cfq5917 resid=39
  8,0    1        0  4847.030331783     0  m   N cfq5917 sl_used=1 disp=7
charge=1 iops=0 sect=96

Hence I think that it is just a chance that both sync and async queues
have got same cfqq->pid. If you just append anohter character to represent
sync and async property of queue, that can cofirm it.

Thanks
Vivek