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
