lkml.org 
[lkml]   [2013]   [Apr]   [3]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: Excessive stall times on ext4 in 3.9-rc2
    On Wed, Apr 03, 2013 at 11:19:25AM +0100, Mel Gorman wrote:
    >
    > I'm running with -rc5 now. I have not noticed much interactivity problems
    > as such but the stall detection script reported that mutt stalled for
    > 20 seconds opening an inbox and imapd blocked for 59 seconds doing path
    > lookups, imaps blocked again for 12 seconds doing an atime update, an RSS
    > reader blocked for 3.5 seconds writing a file. etc.

    If imaps blocked for 12 seconds during an atime update, combined with
    everything else, at a guess it got caught by something holding up a
    journal commit. Could you try enabling the jbd2_run_stats tracepoint
    and grabbing the trace log? This will give you statistics on how long
    (in milliseconds) each of the various phases of a jbd2 commit is
    taking, i.e.:

    jbd2/sdb1-8-327 [002] .... 39681.874661: jbd2_run_stats: dev 8,17 tid 7163786 wait 0 request_delay 0 running 3530 locked 0 flushing 0 logging 0 handle_count 75 blocks 8 blocks_logged 9
    jbd2/sdb1-8-327 [003] .... 39682.514153: jbd2_run_stats: dev 8,17 tid 7163787 wait 0 request_delay 0 running 640 locked 0 flushing 0 logging 0 handle_count 39 blocks 12 blocks_logged 13
    jbd2/sdb1-8-327 [000] .... 39687.665609: jbd2_run_stats: dev 8,17 tid 7163788 wait 0 request_delay 0 running 5150 locked 0 flushing 0 logging 0 handle_count 60 blocks 13 blocks_logged 14
    jbd2/sdb1-8-327 [000] .... 39693.200453: jbd2_run_stats: dev 8,17 tid 7163789 wait 0 request_delay 0 running 4840 locked 0 flushing 0 logging 0 handle_count 53 blocks 10 blocks_logged 11
    jbd2/sdb1-8-327 [001] .... 39695.061657: jbd2_run_stats: dev 8,17 tid 7163790 wait 0 request_delay 0 running 1860 locked 0 flushing 0 logging 0 handle_count 124 blocks 19 blocks_logged 20

    In the above sample each journal commit is running for no more than 5
    seconds or so (since that's the default jbd2 commit timeout; if a
    transaction is running for less than 5 seconds, then either we ran out
    of room in the journal, and the blocks_logged number will be high, or
    a commit was forced by something such as an fsync call).

    If an atime update is getting blocked by 12 seconds, then it would be
    interesting to see if a journal commit is running for significantly
    longer than 5 seconds, or if one of the other commit phases is taking
    significant amounts of time. (On the example above they are all
    taking no time, since I ran this on a relatively uncontended system;
    only a single git operation taking place.)

    Something else that might be worth trying is grabbing a lock_stat
    report and see if something is sitting on an ext4 or jbd2 mutex for a
    long time.

    Finally, as I mentioned I tried some rather simplistic tests and I
    didn't notice any difference between a 3.2 kernel and a 3.8/3.9-rc5
    kernel. Assuming you can get a version of systemtap that
    simultaneously works on 3.2 and 3.9-rc5 :-P, and chance you could do a
    quick experiment and see if you're seeing a difference on your setup?

    Thanks!!

    - Ted


    \
     
     \ /
      Last update: 2013-04-03 14:21    [W:2.966 / U:0.652 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site