Re: Excessive stall times on ext4 in 3.9-rc2

[Mel Gorman]

On Wed, Apr 03, 2013 at 08:05:30AM -0400, Theodore Ts'o wrote:
> 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. 

It's a possibility.

I apologise but I forgot that mail is stored on a crypted partition on
this machine. It's formatted ext4 but dmcrypt could be making this problem
worse if it's stalling ext4 waiting to encrypt/decrypt data due to either
a scheduler or workqueue change.

> 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
> 

Attached as well as the dstate summary that was recorded at the same
time. It's not quite as compelling but I'll keep the monitor running and
see if something falls out. I didn't find anything useful in the existing
mmtests tests that could be used to bisect this but not many of them are
focused on IO.

> 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).  
> 

I didn't see anything majorly compelling in the jbd tracepoints but I'm
not 100% sure I'm looking for the right thing either. I also recorded
/proc/latency_stat and there were some bad sync latencies from the file
as you can see here

3 4481 1586 jbd2_log_wait_commit ext4_sync_file vfs_fsync sys_msync system_call_fastpath
3 11325 4373 sleep_on_page wait_on_page_bit kretprobe_trampoline filemap_write_and_wait_range ext4_sync_file vfs_fsync sys_msync system_call_fastpath
85 1130707 14904 jbd2_journal_stop jbd2_journal_force_commit ext4_force_commit ext4_sync_file do_fsync sys_fsync system_call_fastpath
1 2161073 2161073 start_this_handle jbd2__journal_start.part.8 jbd2__journal_start __ext4_journal_start_sb ext4_da_writepages do_writepages __filemap_fdatawrite_range filemap_write_and_wait_range ext4_sync_file do_fsync sys_fsync system_call_fastpath
118 7798435 596184 jbd2_log_wait_commit jbd2_journal_stop jbd2_journal_force_commit ext4_force_commit ext4_sync_file do_fsync sys_fsync system_call_fastpath
599 15496449 3405822 sleep_on_page wait_on_page_bit kretprobe_trampoline filemap_write_and_wait_range ext4_sync_file do_fsync sys_fsync system_call_fastpath
405 28572881 2619592 jbd2_log_wait_commit ext4_sync_file do_fsync sys_fsync system_call_fastpath


> 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.
> 

Ok, if nothing useful falls out in this session I'll enable lock
debugging. latency_stat on its own would not be enough to conclude that
a problem was related to lock contention.

> 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?
> 

stap-fix.sh should be able to kick systemtap sufficiently hard for
either 3.2 or 3.9-rc5 to keep it working. I'll keep digging when I can.

-- 
Mel Gorman
SUSE Labs
Overall stalled time: 242940 ms

Time stalled in this event:    59077 ms
Event count:                       4
mutt                 sleep_on_buffer        1980 ms
latency-output       sleep_on_buffer       20272 ms
latency-output       sleep_on_buffer       19789 ms
tclsh                sleep_on_buffer       17036 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff811f3198>] ext4_reserve_inode_write+0x78/0xa0
[<ffffffff811f3209>] ext4_mark_inode_dirty+0x49/0x220
[<ffffffff811f57d1>] ext4_dirty_inode+0x41/0x60
[<ffffffff8119ac3e>] __mark_inode_dirty+0x4e/0x2d0
[<ffffffff8118b9b9>] update_time+0x79/0xc0
[<ffffffff8118ba98>] file_update_time+0x98/0x100
[<ffffffff81110ffc>] __generic_file_aio_write+0x17c/0x3b0
[<ffffffff811112aa>] generic_file_aio_write+0x7a/0xf0
[<ffffffff811ea853>] ext4_file_write+0x83/0xd0
[<ffffffff81172b23>] do_sync_write+0xa3/0xe0
[<ffffffff811731ae>] vfs_write+0xae/0x180
[<ffffffff8117361d>] sys_write+0x4d/0x90
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:    50129 ms
Event count:                       1
offlineimap          sleep_on_buffer       50129 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a3996>] __wait_on_buffer+0x26/0x30
[<ffffffff811f9b45>] ext4_find_entry+0x325/0x4f0
[<ffffffff811f9d39>] ext4_lookup.part.31+0x29/0x140
[<ffffffff811f9e75>] ext4_lookup+0x25/0x30
[<ffffffff8117c828>] lookup_real+0x18/0x50
[<ffffffff8117cc63>] __lookup_hash+0x33/0x40
[<ffffffff81585a23>] lookup_slow+0x40/0xa4
[<ffffffff8117f1b2>] path_lookupat+0x222/0x780
[<ffffffff8117f73f>] filename_lookup+0x2f/0xc0
[<ffffffff81182274>] user_path_at_empty+0x54/0xa0
[<ffffffff811822cc>] user_path_at+0xc/0x10
[<ffffffff81177d39>] vfs_fstatat+0x49/0xa0
[<ffffffff81177dc6>] vfs_stat+0x16/0x20
[<ffffffff81177ee5>] sys_newstat+0x15/0x30
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:    29283 ms
Event count:                       5
latency-output       wait_on_page_bit       6482 ms
tclsh                wait_on_page_bit       7756 ms
mutt                 wait_on_page_bit       7702 ms
latency-output       wait_on_page_bit       6017 ms
latency-output       wait_on_page_bit       1326 ms
[<ffffffff8110f180>] wait_on_page_bit+0x70/0x80
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff8110f44a>] generic_perform_write+0xca/0x210
[<ffffffff8110f5e8>] generic_file_buffered_write+0x58/0x90
[<ffffffff81111036>] __generic_file_aio_write+0x1b6/0x3b0
[<ffffffff811112aa>] generic_file_aio_write+0x7a/0xf0
[<ffffffff811ea853>] ext4_file_write+0x83/0xd0
[<ffffffff81172b23>] do_sync_write+0xa3/0xe0
[<ffffffff811731ae>] vfs_write+0xae/0x180
[<ffffffff8117361d>] sys_write+0x4d/0x90
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:    21871 ms
Event count:                       2
imapd                sleep_on_buffer       18495 ms
imapd                sleep_on_buffer        3376 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff811f3198>] ext4_reserve_inode_write+0x78/0xa0
[<ffffffff811f3209>] ext4_mark_inode_dirty+0x49/0x220
[<ffffffff811f57d1>] ext4_dirty_inode+0x41/0x60
[<ffffffff8119ac3e>] __mark_inode_dirty+0x4e/0x2d0
[<ffffffff8118b9b9>] update_time+0x79/0xc0
[<ffffffff8118bc61>] touch_atime+0x161/0x170
[<ffffffff81110683>] do_generic_file_read.constprop.35+0x363/0x440
[<ffffffff811113f9>] generic_file_aio_read+0xd9/0x220
[<ffffffff81172c03>] do_sync_read+0xa3/0xe0
[<ffffffff8117332b>] vfs_read+0xab/0x170
[<ffffffff8117358d>] sys_read+0x4d/0x90
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:    20849 ms
Event count:                       1
awesome              sleep_on_buffer       20849 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff811f3198>] ext4_reserve_inode_write+0x78/0xa0
[<ffffffff811fbd0f>] ext4_orphan_add+0x10f/0x1f0
[<ffffffff811f37b4>] ext4_setattr+0x3d4/0x640
[<ffffffff8118d362>] notify_change+0x1f2/0x3c0
[<ffffffff81171689>] do_truncate+0x59/0xa0
[<ffffffff8117d386>] handle_truncate+0x66/0xa0
[<ffffffff81181506>] do_last+0x626/0x820
[<ffffffff811817b3>] path_openat+0xb3/0x4a0
[<ffffffff8118230d>] do_filp_open+0x3d/0xa0
[<ffffffff811727f9>] do_sys_open+0xf9/0x1e0
[<ffffffff811728fc>] sys_open+0x1c/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     7872 ms
Event count:                       1
dconf-service        sleep_on_buffer        7872 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a3996>] __wait_on_buffer+0x26/0x30
[<ffffffff811f9b45>] ext4_find_entry+0x325/0x4f0
[<ffffffff811fbef5>] ext4_rename+0x105/0x980
[<ffffffff8117d6ed>] vfs_rename_other+0xcd/0x120
[<ffffffff81180326>] vfs_rename+0xb6/0x240
[<ffffffff81182e96>] sys_renameat+0x386/0x3d0
[<ffffffff81182ef6>] sys_rename+0x16/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     6265 ms
Event count:                       3
dconf-service        wait_on_page_bit       3486 ms
pool                 wait_on_page_bit       1059 ms
Cache I/O            wait_on_page_bit       1720 ms
[<ffffffff8110f180>] wait_on_page_bit+0x70/0x80
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff81110cf0>] filemap_write_and_wait_range+0x60/0x70
[<ffffffff811ea9fa>] ext4_sync_file+0x6a/0x2d0
[<ffffffff811a1b88>] do_fsync+0x58/0x80
[<ffffffff811a1eeb>] sys_fsync+0xb/0x10
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     5349 ms
Event count:                       1
dconf-service        sleep_on_buffer        5349 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff81227c94>] ext4_mb_mark_diskspace_used+0x74/0x4d0
[<ffffffff812293af>] ext4_mb_new_blocks+0x2af/0x490
[<ffffffff8121fbb1>] ext4_ext_map_blocks+0x501/0xa00
[<ffffffff811f0455>] ext4_map_blocks+0x2d5/0x470
[<ffffffff811f451a>] mpage_da_map_and_submit+0xba/0x2f0
[<ffffffff811f5020>] ext4_da_writepages+0x380/0x620
[<ffffffff8111aceb>] do_writepages+0x1b/0x30
[<ffffffff81110c89>] __filemap_fdatawrite_range+0x49/0x50
[<ffffffff81110cda>] filemap_write_and_wait_range+0x4a/0x70
[<ffffffff811ea9fa>] ext4_sync_file+0x6a/0x2d0
[<ffffffff811a1b88>] do_fsync+0x58/0x80
[<ffffffff811a1eeb>] sys_fsync+0xb/0x10
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     5168 ms
Event count:                       2
evolution            wait_on_page_bit_killable   1177 ms
firefox              wait_on_page_bit_killable   3991 ms
[<ffffffff81111668>] wait_on_page_bit_killable+0x78/0x80
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff81111b18>] filemap_fault+0x3d8/0x410
[<ffffffff81135b2a>] __do_fault+0x6a/0x530
[<ffffffff8113964e>] handle_pte_fault+0xee/0x200
[<ffffffff8113a8c1>] handle_mm_fault+0x271/0x390
[<ffffffff81598e29>] __do_page_fault+0x169/0x520
[<ffffffff815991e9>] do_page_fault+0x9/0x10
[<ffffffff81595948>] page_fault+0x28/0x30
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     4929 ms
Event count:                       1
flush-253:0          sleep_on_buffer        4929 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff81227c94>] ext4_mb_mark_diskspace_used+0x74/0x4d0
[<ffffffff812293af>] ext4_mb_new_blocks+0x2af/0x490
[<ffffffff8121fbb1>] ext4_ext_map_blocks+0x501/0xa00
[<ffffffff811f0455>] ext4_map_blocks+0x2d5/0x470
[<ffffffff811f451a>] mpage_da_map_and_submit+0xba/0x2f0
[<ffffffff811f5020>] ext4_da_writepages+0x380/0x620
[<ffffffff8111aceb>] do_writepages+0x1b/0x30
[<ffffffff81199ce0>] __writeback_single_inode+0x40/0x1b0
[<ffffffff8119c38a>] writeback_sb_inodes+0x19a/0x350
[<ffffffff8119c5d6>] __writeback_inodes_wb+0x96/0xc0
[<ffffffff8119c87b>] wb_writeback+0x27b/0x330
[<ffffffff8119e280>] wb_do_writeback+0x190/0x1d0
[<ffffffff8119e343>] bdi_writeback_thread+0x83/0x280
[<ffffffff8106901b>] kthread+0xbb/0xc0
[<ffffffff8159d57c>] ret_from_fork+0x7c/0xb0
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     4840 ms
Event count:                       1
systemd-journal      sleep_on_buffer        4840 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff81227c94>] ext4_mb_mark_diskspace_used+0x74/0x4d0
[<ffffffff812293af>] ext4_mb_new_blocks+0x2af/0x490
[<ffffffff8121fbb1>] ext4_ext_map_blocks+0x501/0xa00
[<ffffffff811f0455>] ext4_map_blocks+0x2d5/0x470
[<ffffffff8122045f>] ext4_fallocate+0x1cf/0x420
[<ffffffff81171be2>] do_fallocate+0x112/0x190
[<ffffffff81171cb2>] sys_fallocate+0x52/0x90
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     4739 ms
Event count:                       1
pool                 sleep_on_buffer        4739 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff811f3198>] ext4_reserve_inode_write+0x78/0xa0
[<ffffffff811f3209>] ext4_mark_inode_dirty+0x49/0x220
[<ffffffff811fb47e>] ext4_link+0x10e/0x1b0
[<ffffffff81182033>] vfs_link+0x113/0x1c0
[<ffffffff81182aa4>] sys_linkat+0x174/0x1c0
[<ffffffff81182b09>] sys_link+0x19/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     3358 ms
Event count:                       2
imapd                wait_on_page_bit       1726 ms
imapd                wait_on_page_bit       1632 ms
[<ffffffff8110f180>] wait_on_page_bit+0x70/0x80
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff8111d700>] truncate_inode_pages+0x10/0x20
[<ffffffff811f53cf>] ext4_evict_inode+0x10f/0x4d0
[<ffffffff8118beef>] evict+0xaf/0x1b0
[<ffffffff8118c771>] iput_final+0xd1/0x160
[<ffffffff8118c839>] iput+0x39/0x50
[<ffffffff81187418>] dentry_iput+0x98/0xe0
[<ffffffff81188cb8>] dput+0x128/0x230
[<ffffffff81182e4a>] sys_renameat+0x33a/0x3d0
[<ffffffff81182ef6>] sys_rename+0x16/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     3294 ms
Event count:                       1
imapd                sleep_on_buffer        3294 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a3996>] __wait_on_buffer+0x26/0x30
[<ffffffff811f9b45>] ext4_find_entry+0x325/0x4f0
[<ffffffff811fca21>] ext4_unlink+0x41/0x350
[<ffffffff8117dcef>] vfs_unlink.part.31+0x7f/0xe0
[<ffffffff8117fbd7>] vfs_unlink+0x37/0x50
[<ffffffff8117fdff>] do_unlinkat+0x20f/0x260
[<ffffffff81182811>] sys_unlink+0x11/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     2608 ms
Event count:                       1
pool                 sleep_on_buffer        2608 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff812298fa>] ext4_free_blocks+0x36a/0xbe0
[<ffffffff8121c3b6>] ext4_remove_blocks+0x256/0x2d0
[<ffffffff8121c635>] ext4_ext_rm_leaf+0x205/0x520
[<ffffffff8121e37c>] ext4_ext_remove_space+0x4dc/0x750
[<ffffffff8122024b>] ext4_ext_truncate+0x19b/0x1e0
[<ffffffff811efb25>] ext4_truncate.part.60+0xd5/0xf0
[<ffffffff811f0c24>] ext4_truncate+0x34/0x90
[<ffffffff811f356d>] ext4_setattr+0x18d/0x640
[<ffffffff8118d362>] notify_change+0x1f2/0x3c0
[<ffffffff81171689>] do_truncate+0x59/0xa0
[<ffffffff8117d386>] handle_truncate+0x66/0xa0
[<ffffffff81181506>] do_last+0x626/0x820
[<ffffffff811817b3>] path_openat+0xb3/0x4a0
[<ffffffff8118230d>] do_filp_open+0x3d/0xa0
[<ffffffff811727f9>] do_sys_open+0xf9/0x1e0
[<ffffffff811728fc>] sys_open+0x1c/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     2546 ms
Event count:                       1
offlineimap          sleep_on_buffer        2546 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff811fa412>] ext4_dx_add_entry+0xc2/0x590
[<ffffffff811faf65>] ext4_add_entry+0x265/0x2d0
[<ffffffff811fc556>] ext4_rename+0x766/0x980
[<ffffffff8117d6ed>] vfs_rename_other+0xcd/0x120
[<ffffffff81180326>] vfs_rename+0xb6/0x240
[<ffffffff81182e96>] sys_renameat+0x386/0x3d0
[<ffffffff81182ef6>] sys_rename+0x16/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     2199 ms
Event count:                       1
folder-markup.s      sleep_on_buffer        2199 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a39de>] __lock_buffer+0x2e/0x30
[<ffffffff8123a60f>] do_get_write_access+0x43f/0x4b0
[<ffffffff8123a7cb>] jbd2_journal_get_write_access+0x2b/0x50
[<ffffffff81220f79>] __ext4_journal_get_write_access+0x39/0x80
[<ffffffff811fa412>] ext4_dx_add_entry+0xc2/0x590
[<ffffffff811faf65>] ext4_add_entry+0x265/0x2d0
[<ffffffff811faff6>] ext4_add_nondir+0x26/0x80
[<ffffffff811fb2df>] ext4_create+0xff/0x190
[<ffffffff81180ca5>] vfs_create+0xb5/0x120
[<ffffffff81180e4e>] lookup_open+0x13e/0x1d0
[<ffffffff811811e7>] do_last+0x307/0x820
[<ffffffff811817b3>] path_openat+0xb3/0x4a0
[<ffffffff8118230d>] do_filp_open+0x3d/0xa0
[<ffffffff811727f9>] do_sys_open+0xf9/0x1e0
[<ffffffff811728fc>] sys_open+0x1c/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     2124 ms
Event count:                       2
evolution            sleep_on_buffer        1088 ms
imapd                sleep_on_buffer        1036 ms
[<ffffffff8110efb2>] __lock_page_killable+0x62/0x70
[<ffffffff811105a7>] do_generic_file_read.constprop.35+0x287/0x440
[<ffffffff811113f9>] generic_file_aio_read+0xd9/0x220
[<ffffffff81172c03>] do_sync_read+0xa3/0xe0
[<ffffffff8117332b>] vfs_read+0xab/0x170
[<ffffffff8117358d>] sys_read+0x4d/0x90
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     1220 ms
Event count:                       1
jbd2/dm-0-8          sleep_on_buffer        1220 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a3996>] __wait_on_buffer+0x26/0x30
[<ffffffff8123c6d1>] jbd2_journal_commit_transaction+0x1241/0x13c0
[<ffffffff81240d33>] kjournald2+0xb3/0x240
[<ffffffff8106901b>] kthread+0xbb/0xc0
[<ffffffff8159d57c>] ret_from_fork+0x7c/0xb0
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     1088 ms
Event count:                       1
firefox              sleep_on_buffer        1088 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a3996>] __wait_on_buffer+0x26/0x30
[<ffffffff811ef5de>] __ext4_get_inode_loc+0x1be/0x3f0
[<ffffffff811f133e>] ext4_iget+0x7e/0x940
[<ffffffff811f9dd6>] ext4_lookup.part.31+0xc6/0x140
[<ffffffff811f9e75>] ext4_lookup+0x25/0x30
[<ffffffff8117c828>] lookup_real+0x18/0x50
[<ffffffff8117cc63>] __lookup_hash+0x33/0x40
[<ffffffff81585a23>] lookup_slow+0x40/0xa4
[<ffffffff8117f1b2>] path_lookupat+0x222/0x780
[<ffffffff8117f73f>] filename_lookup+0x2f/0xc0
[<ffffffff81182274>] user_path_at_empty+0x54/0xa0
[<ffffffff811822cc>] user_path_at+0xc/0x10
[<ffffffff81171d87>] sys_faccessat+0x97/0x220
[<ffffffff81171f23>] sys_access+0x13/0x20
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     1076 ms
Event count:                       1
imapd                sleep_on_buffer        1076 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a3996>] __wait_on_buffer+0x26/0x30
[<ffffffff811e7cc8>] ext4_wait_block_bitmap+0xb8/0xc0
[<ffffffff81224d6e>] ext4_mb_init_cache+0x1ce/0x730
[<ffffffff8122536e>] ext4_mb_init_group+0x9e/0x100
[<ffffffff812254d7>] ext4_mb_good_group+0x107/0x1a0
[<ffffffff81227973>] ext4_mb_regular_allocator+0x183/0x430
[<ffffffff812294f6>] ext4_mb_new_blocks+0x3f6/0x490
[<ffffffff8121fbb1>] ext4_ext_map_blocks+0x501/0xa00
[<ffffffff811f0455>] ext4_map_blocks+0x2d5/0x470
[<ffffffff811f451a>] mpage_da_map_and_submit+0xba/0x2f0
[<ffffffff811f5020>] ext4_da_writepages+0x380/0x620
[<ffffffff8111aceb>] do_writepages+0x1b/0x30
[<ffffffff81110c89>] __filemap_fdatawrite_range+0x49/0x50
[<ffffffff81111557>] filemap_flush+0x17/0x20
[<ffffffff811f0964>] ext4_alloc_da_blocks+0x44/0xa0
[<ffffffff811ea6b1>] ext4_release_file+0x61/0xd0
[<ffffffff811744a0>] __fput+0xb0/0x240
[<ffffffff81174639>] ____fput+0x9/0x10
[<ffffffff81065cf7>] task_work_run+0x97/0xd0
[<ffffffff81002cbc>] do_notify_resume+0x9c/0xb0
[<ffffffff8159d8ea>] int_signal+0x12/0x17
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     1042 ms
Event count:                       1
offlineimap          wait_on_page_bit       1042 ms
[<ffffffff811eab95>] ext4_sync_file+0x205/0x2d0
[<ffffffff811a1b88>] do_fsync+0x58/0x80
[<ffffffff811a1eeb>] sys_fsync+0xb/0x10
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     1011 ms
Event count:                       1
firefox              sleep_on_buffer        1011 ms
[<ffffffff81597b84>] kretprobe_trampoline+0x0/0x4c
[<ffffffff811a3996>] __wait_on_buffer+0x26/0x30
[<ffffffff811ef5de>] __ext4_get_inode_loc+0x1be/0x3f0
[<ffffffff811f133e>] ext4_iget+0x7e/0x940
[<ffffffff811f9dd6>] ext4_lookup.part.31+0xc6/0x140
[<ffffffff811f9e75>] ext4_lookup+0x25/0x30
[<ffffffff8117c828>] lookup_real+0x18/0x50
[<ffffffff8117cc63>] __lookup_hash+0x33/0x40
[<ffffffff81585a23>] lookup_slow+0x40/0xa4
[<ffffffff8117f1b2>] path_lookupat+0x222/0x780
[<ffffffff8117f73f>] filename_lookup+0x2f/0xc0
[<ffffffff81182274>] user_path_at_empty+0x54/0xa0
[<ffffffff811822cc>] user_path_at+0xc/0x10
[<ffffffff81177d39>] vfs_fstatat+0x49/0xa0
[<ffffffff81177dc6>] vfs_stat+0x16/0x20
[<ffffffff81177ee5>] sys_newstat+0x15/0x30
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:     1003 ms
Event count:                       1
folder-markup.s      sleep_on_buffer        1003 ms
[<ffffffff8117bb0e>] pipe_read+0x20e/0x340
[<ffffffff81172c03>] do_sync_read+0xa3/0xe0
[<ffffffff8117332b>] vfs_read+0xab/0x170
[<ffffffff8117358d>] sys_read+0x4d/0x90
[<ffffffff8159d62d>] system_call_fastpath+0x1a/0x1f
[<ffffffffffffffff>] 0xffffffffffffffff

Time stalled in this event:        0 ms
Event count:                       1

Attachment: ftrace-debug-stalls-monitor.gz
Description: GNU Zip compressed data