lkml.org 
[lkml]   [2012]   [Jun]   [21]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
SubjectRe: multi-second application stall in open()
From
On Thu, Jun 21, 2012 at 3:32 PM, Vivek Goyal <vgoyal@redhat.com> wrote:
> On Thu, Jun 21, 2012 at 02:26:13PM -0500, Josh Hunt wrote:
>> On Thu, Mar 8, 2012 at 6:16 PM, Josh Hunt <joshhunt00@gmail.com> wrote:
>> > On Thu, Mar 8, 2012 at 5:40 PM, Vivek Goyal <vgoyal@redhat.com> wrote:
>> >> On Thu, Mar 08, 2012 at 04:22:31PM -0600, Josh Hunt wrote:
>> >>
>> >> [..]
>> >>> A crude bisection seems to show that if I revert "blkio: Set
>> >>> must_dispatch only if we decided to not dispatch the request"
>> >>> (bf7919371025412978268efca4b09dd847acb395) I no longer see the stalls
>> >>> in 2.6.35. However this does not seem to solve the problem if I revert
>> >>> it in 2.6.38.
>> >>
>> >> Strange. If this was the problem it should have fixed it in 2.6.38 also.
>> >> BTW, the blktrace you sent was from 2.6.38 or 2.6.35 kernels.
>> >>
>> >
>> > The blktrace is from 2.6.35. I just attached a portion of it earlier
>> > b/c I thought it would be too much to send the whole thing. I've gone
>> > ahead and attached the full output (bzip'd), along with the same
>> > workload with slice_idle set to 0 for comparison.
>> >
>> >>>
>> >>> By setting slice_idle to 0, does this basically disable plugging?
>> >>
>> >> It disables idling and not plugging.
>> >
>> > OK that's what I thought. I'm just confused about the differences in
>> > the blktrace outputs wrt plugging with slice_idle set to 0.
>> >
>> >>
>> >>> Based on the blktrace info it seems that something is going wrong with
>> >>> plugging with my testcase. I'm just wondering why setting slice_idle
>> >>> to 0 seems to resolve my issue? Also, since we see unplugs in the
>> >>> blktrace how could the requests still not be getting sent to the disk?
>> >>
>> >> Unplug will just try to kick the queue. That does not mean that request
>> >> will be dispatched. And that's the question that why are we not
>> >> dispatching requests.
>> >>
>> >> I had another look at traces and I think it is not just async write, but
>> >> there is was sync write request queued and we have not dispatched that
>> >> too for a long time.
>> >>
>> >> Added request here.
>> >>
>> >>  8,0    1    36921  5028.492019664   162  A  WS 63 + 8 <- (8,1) 0
>> >>  8,0    1    36922  5028.492021620   162  Q  WS 63 + 8 [sync_supers]
>> >>  8,0    1    36923  5028.492029721   162  G  WS 63 + 8 [sync_supers]
>> >>  8,0    1    36924  5028.492040617   162  I   W 63 + 8 (   10896)
>> >> [sync_supers]
>> >>  8,0    1        0  5028.492044807     0  m   N cfq162 insert_request
>> >>  8,0    1        0  5028.492046763     0  m   N cfq162 add_to_rr
>> >>
>> >> And after a long time we dispatched the request.
>> >>
>> >>  8,0    0        0  5050.116841906     0  m   N cfq162 set_active wl_prio:0 wl_type:1
>> >>  8,0    0        0  5050.116844979     0  m   N cfq162 fifo=ffff8800e8787aa0
>> >>  8,0    0        0  5050.116846655     0  m   N cfq162 dispatch_insert
>> >>  8,0    0        0  5050.116849728     0  m   N cfq162 dispatched a
>> >> request
>> >>  8,0    0        0  5050.116851683     0  m   N cfq162 activate rq, drv=1
>> >>  8,0    0    36518  5050.116853360   166  D   W 63 + 8 (21624812743)
>> >> [kblockd/0]
>> >>  8,0    0    36519  5050.117236650  9671  C   W 63 + 8 (  383290) [0]
>> >>
>> >> So it is not async requestss being starved by sync request issue, most
>> >> likely.
>> >>
>> >
>> > I wanted to point out again that this is a very small io load. On the
>> > avg of a few KB/s.
>> >
>> >> Are you using any of the blk cgroup stuff?
>> >
>> > No, none of that is enabled in the kernel.
>> >
>> >>
>> >> Can you put some more trace messages to figure out what's happening.
>> >> I think you can try putting some trace messages in following functions.
>> >>
>> >> __blk_run_queue()
>> >> cfq_select_queue()
>> >>
>> >> and try to narrow down why CFQ refuses to dispatch the request when
>> >> this happens.
>> >
>> > Sure. I'll add some more traces here and see if it sheds any light on the issue.
>> >
>> > Thanks again for your help.
>> >
>> >>
>> >> Thanks
>> >> Vivek
>> >
>> > --
>> > Josh
>>
>> It looks like I am hitting this issue again. I upgraded our system to
>> the 3.0.13 kernel and it appeared to resolve the issues I was seeing.
>> Unfortunately it is still occurring now just less frequently.
>>
>> I've gone ahead and instrumented cfq_select_queue and have some more
>> information. To quickly recap my issue - using CFQ we are seeing an
>> application's async writes stall for 5-15s. This is using a sata_svw
>> controller and a rotating drive which does not have NCQ enabled. If I
>> change slice_idle to 0 the stalls appear to go away. I've also tried
>> using the deadline scheduler and do not see the issue with that. I dug
>> through CFQ and identified the line which with slice_idle set to 0
>> gets bypassed and allows my workload to run without stalling (I added
>> in the blktrace logging for my debugging):
>>
>>         if (cfqq->dispatched && cfq_should_idle(cfqd, cfqq)) {
>>                 service_tree = cfqq->service_tree;
>>                 cfq_log_cfqq(cfqd, cfqq, "keep_queue st->count:%d, dispatch:%u",
>>                         service_tree->count, cfqq->dispatched);
>>                 cfqq = NULL;
>>                 goto keep_queue;
>>         }
>>
>> When I have slice_idle set to 0, this gets bypassed and my workload
>> runs fine. I've verified this by removing this code and running the
>> workload with that kernel. I'm not saying it should be removed, just
>> that bypassing this code helps my workload for whatever reason.
>>
>> Here are some snippets from my blktrace log (attached):
>>
>> Insert:
>>   8,0    1        0  4466.115833485     0  m   N cfq5864 insert_request
>>   8,0    1        0  4466.115835161     0  m   N cfq20720 Idling.
>> st->count:2, hw_tag:0
>>   8,0    1  1499412  4466.115836278  6023  I   W 7078615 + 256 (
>> 311495) [flush-8:0]
>>   8,0    1        0  4466.115837675     0  m   N cfq5864 insert_request
>>   8,0    1        0  4466.115840190     0  m   N cfq20720 Idling.
>> st->count:2, hw_tag:0
>>   8,0    1  1499413  4466.115841307  6023  U   N [flush-8:0] 8
>>   8,0    1        0  4466.115842983     0  m   N cfq20720 Idling.
>> st->count:2, hw_tag:0
>>   8,0    1        0  4466.115844660     0  m   N cfq20720 keep_queue
>> st->count:2, dispatch:1
>>
>> Dispatch:
>>   8,0    0        0  4478.127274376     0  m   N cfq5864 complete rqnoidle 0
>>   8,0    0        0  4478.127318796     0  m   N cfq5864 Not idling. st->count:1
>>   8,0    0        0  4478.127320472     0  m   N cfq5864 dispatch_insert
>>   8,0    0        0  4478.127322148     0  m   N cfq5864 dispatched a request
>>   8,0    0        0  4478.127324104     0  m   N cfq5864 activate rq, drv=2
>>   8,0    0  2876000  4478.127325221  7232  D   W 7078615 + 256
>> (12011488943) [testd]
>>   8,0    0  2876001  4478.128414478  7232  C   W 7078135 + 264 ( 1250173) [0]
>>   8,0    0        0  4478.128445767     0  m   N cfq5864 complete rqnoidle 0
>>
>> Also in the blktrace I see gaps of 3-4s where nothing happens:
>>  8,0    0        0  4466.893959719     0  m   N cfq20723 del_from_rr
>>   8,0    0        0  4466.893961395     0  m   N cfq schedule dispatch
>>   8,0    1  1499539  4470.000135552   174  A  WS 63 + 8 <- (8,1) 0
>>   8,0    1  1499540  4470.000138066   174  Q  WS 63 + 8 [sync_supers]
>>
>> Meanwhile the requests issued earlier are just sitting on the queue
>> waiting to be dispatched.
>>
>> To accelerate the issue I'm constantly dropping the cache - while :;
>> do echo 1 > /proc/sys/vm/drop_caches; done. The issue occurs without
>> it, but this helps reproduce it in about an hour. I also wanted to
>> point out that I see a decent amount of syslogd activity in the trace
>> and know that it does do fsync(). I'm not sure if that's helping the
>> stalling, but wanted to mention that.
>
> This is strange. I can see in logs that for some reason writes are not
> being dispatched and queue is doing nothing.
>
>  8,0    0        0  4466.132851211     0  m   N cfq schedule dispatch
>  8,0    0        0  4466.132854564     0  m   N cfq20720 keep_queue
> timer_pending st->count:2, dispatch:0
>  8,0    0        0  4466.139951919     0  m   N cfq idle timer fired
>  8,0    0        0  4466.139954713     0  m   N cfq20720 slice expired
> t=0
>  8,0    0        0  4466.139958066     0  m   N cfq20720 sl_used=17
> disp=21 charge=17 iops=0 sect=176
>  8,0    0        0  4466.139959742     0  m   N cfq20720 del_from_rr
>  8,0    0        0  4466.139963653     0  m   N cfq schedule dispatch
>  8,0    1  1499521  4466.791207736  7570  A   R 7258191 + 8 <- (8,1)
> 7258128
>  8,0    1  1499522  4466.791209692  7570  Q   R 7258191 + 8 [httpdmon]
>  8,0    1  1499523  4466.791217514  7570  G   R 7258191 + 8 [httpdmon]
>  8,0    1  1499524  4466.791221705  7570  I   R 7258191 + 8 (    4191)
> [httpdmon]
>  8,0    1        0  4466.791227572     0  m   N cfq7570 insert_request
>  8,0    1        0  4466.791229248     0  m   N cfq7570 add_to_rr
>  8,0    1        0  4466.791235953     0  m   N cfq20719 set_active
> wl_prio:0 wl_type:2
>
> Here we deleted queue 20720 and did nothing for .6 seconds and from
> previous logs it is visible that writes are pending and queued.
>
> For some reason cfq_schedule_dispatch() did not lead to kicking queue
> or queue was kicked but somehow write queue was not selected for
> dispatch (A case of corrupt data structures?).
>
> Are you able to reproduce this issue on latest kernels (3.5-rc2?). I would

I cannot do it with my current application, but will try doing it another way.

> say put some logs in select_queue() and see where did it bail out. That

Well I did add some instrumentation in select_queue, the "keep_queue
st->count:%d, dispatch:%u" line I mentioned above, but I will add more
and retest.

I'm attaching a similar run with no stalls when I set slice_idle to 0.

> will confirm that select queue was called and can also give some details
> why we did not select async queue for dispatch. (Note: select_queue is called
> multiple times so putting trace point there makes logs very verbose).
>
> Thanks
> Vivek
--
Josh
[unhandled content-type:application/x-bzip2]
\
 
 \ /
  Last update: 2012-06-22 00:01    [W:0.094 / U:0.336 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site