* [2.6.32 ubuntu] I/O hang at start_this_handle @ 2011-02-08 5:26 Tetsuo Handa 2011-02-15 15:16 ` Jan Kara 0 siblings, 1 reply; 11+ messages in thread From: Tetsuo Handa @ 2011-02-08 5:26 UTC (permalink / raw) To: linux-fsdevel I got below hangup. Is this known problem? Installing: grub-0.97-173.6 [91%] # dmesg [14280.252030] INFO: task sh:17496 blocked for more than 120 seconds. [14280.252228] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [14280.252447] sh D 00000000 0 17496 17470 0x00000000 [14280.252455] f6f8fcf8 00200082 c02084a3 00000000 00000000 c088e4c0 f6d39c24 c088e4c0 [14280.252468] 15e72f78 00000ccd c088e4c0 c088e4c0 f6d39c24 c088e4c0 c088e4c0 f40c2a80 [14280.252480] 15e50702 00000ccd f6d39980 f4d2b63c f4d2b600 00000000 f6f8fd54 c02c7ead [14280.252492] Call Trace: [14280.252503] [<c02084a3>] ? __slab_alloc+0x163/0x220 [14280.252512] [<c02c7ead>] start_this_handle+0x22d/0x390 [14280.252519] [<c016ff90>] ? autoremove_wake_function+0x0/0x50 [14280.252525] [<c02c8188>] journal_start+0x98/0xd0 [14280.252532] [<c027b06e>] ext3_journal_start_sb+0x2e/0x50 [14280.252538] [<c0272f02>] ext3_dirty_inode+0x32/0x80 [14280.252545] [<c0231c71>] __mark_inode_dirty+0x31/0x180 [14280.252552] [<c022900a>] inode_setattr+0xaa/0x170 [14280.252557] [<c0273091>] ext3_setattr+0x141/0x1f0 [14280.252563] [<c0229213>] notify_change+0x143/0x340 [14280.252571] [<c02122d2>] do_truncate+0x62/0x90 [14280.252578] [<c03018ea>] ? security_path_truncate+0x3a/0x50 [14280.252584] [<c021c710>] may_open+0x1d0/0x200 [14280.252591] [<c021f9fc>] do_filp_open+0xfc/0x990 [14280.252597] [<c01efb74>] ? do_wp_page+0x104/0x910 [14280.252605] [<c02111d5>] do_sys_open+0x55/0x160 [14280.252611] [<c021134e>] sys_open+0x2e/0x40 [14280.252617] [<c01096c3>] sysenter_do_call+0x12/0x28 [14400.252032] INFO: task sh:17496 blocked for more than 120 seconds. [14400.252201] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [14400.252429] sh D 00000000 0 17496 17470 0x00000000 [14400.252437] f6f8fcf8 00200082 c02084a3 00000000 00000000 c088e4c0 f6d39c24 c088e4c0 [14400.252450] 15e72f78 00000ccd c088e4c0 c088e4c0 f6d39c24 c088e4c0 c088e4c0 f40c2a80 [14400.252461] 15e50702 00000ccd f6d39980 f4d2b63c f4d2b600 00000000 f6f8fd54 c02c7ead [14400.252473] Call Trace: [14400.252484] [<c02084a3>] ? __slab_alloc+0x163/0x220 [14400.252492] [<c02c7ead>] start_this_handle+0x22d/0x390 [14400.252500] [<c016ff90>] ? autoremove_wake_function+0x0/0x50 [14400.252506] [<c02c8188>] journal_start+0x98/0xd0 [14400.252512] [<c027b06e>] ext3_journal_start_sb+0x2e/0x50 [14400.252518] [<c0272f02>] ext3_dirty_inode+0x32/0x80 [14400.252525] [<c0231c71>] __mark_inode_dirty+0x31/0x180 [14400.252532] [<c022900a>] inode_setattr+0xaa/0x170 [14400.252537] [<c0273091>] ext3_setattr+0x141/0x1f0 [14400.252543] [<c0229213>] notify_change+0x143/0x340 [14400.252550] [<c02122d2>] do_truncate+0x62/0x90 [14400.252557] [<c03018ea>] ? security_path_truncate+0x3a/0x50 [14400.252564] [<c021c710>] may_open+0x1d0/0x200 [14400.252570] [<c021f9fc>] do_filp_open+0xfc/0x990 [14400.252577] [<c01efb74>] ? do_wp_page+0x104/0x910 [14400.252584] [<c02111d5>] do_sys_open+0x55/0x160 [14400.252590] [<c021134e>] sys_open+0x2e/0x40 [14400.252596] [<c01096c3>] sysenter_do_call+0x12/0x28 CPU usage is almost 0%. Below is some sysrq info. [15460.045190] SysRq : Show Blocked State [15460.053012] task PC stack pid father [15460.053012] sh D 00000000 0 17496 17470 0x00000000 [15460.053012] f6f8fcf8 00200082 c02084a3 00000000 00000000 c088e4c0 f6d39c24 c088e4c0 [15460.053012] 15e72f78 00000ccd c088e4c0 c088e4c0 f6d39c24 c088e4c0 c088e4c0 f40c2a80 [15460.053012] 15e50702 00000ccd f6d39980 f4d2b63c f4d2b600 00000000 f6f8fd54 c02c7ead [15460.053012] Call Trace: [15460.053012] [<c02084a3>] ? __slab_alloc+0x163/0x220 [15460.053012] [<c02c7ead>] start_this_handle+0x22d/0x390 [15460.053012] [<c016ff90>] ? autoremove_wake_function+0x0/0x50 [15460.053012] [<c02c8188>] journal_start+0x98/0xd0 [15460.053012] [<c027b06e>] ext3_journal_start_sb+0x2e/0x50 [15460.053012] [<c0272f02>] ext3_dirty_inode+0x32/0x80 [15460.053012] [<c0231c71>] __mark_inode_dirty+0x31/0x180 [15460.053012] [<c022900a>] inode_setattr+0xaa/0x170 [15460.053012] [<c0273091>] ext3_setattr+0x141/0x1f0 [15460.053012] [<c0229213>] notify_change+0x143/0x340 [15460.053012] [<c02122d2>] do_truncate+0x62/0x90 [15460.053012] [<c03018ea>] ? security_path_truncate+0x3a/0x50 [15460.053012] [<c021c710>] may_open+0x1d0/0x200 [15460.053012] [<c021f9fc>] do_filp_open+0xfc/0x990 [15460.053012] [<c01efb74>] ? do_wp_page+0x104/0x910 [15460.053012] [<c02111d5>] do_sys_open+0x55/0x160 [15460.053012] [<c021134e>] sys_open+0x2e/0x40 [15460.053012] [<c01096c3>] sysenter_do_call+0x12/0x28 [15460.053012] Sched Debug Version: v0.09, 2.6.32-28-generic-pae #55-Ubuntu [15460.053012] now at 15460053.551044 msecs [15460.053012] .jiffies : 3790013 [15460.053012] .sysctl_sched_latency : 10.000000 [15460.053012] .sysctl_sched_min_granularity : 2.000000 [15460.053012] .sysctl_sched_wakeup_granularity : 2.000000 [15460.053012] .sysctl_sched_child_runs_first : 0.000000 [15460.053012] .sysctl_sched_features : 15834235 [15460.053012] [15460.053012] cpu#0, 2194.944 MHz [15460.053012] .nr_running : 1 [15460.053012] .load : 1024 [15460.053012] .nr_switches : 1773885 [15460.053012] .nr_load_updates : 494855 [15460.053012] .nr_uninterruptible : 1 [15460.053012] .next_balance : 3.789648 [15460.053012] .curr->pid : 17674 [15460.053012] .clock : 15460045.031387 [15460.053012] .cpu_load[0] : 0 [15460.053012] .cpu_load[1] : 0 [15460.053012] .cpu_load[2] : 0 [15460.053012] .cpu_load[3] : 0 [15460.053012] .cpu_load[4] : 0 [15460.053012] .yld_count : 1006 [15460.053012] .sched_switch : 0 [15460.053012] .sched_count : 1819077 [15460.053012] .sched_goidle : 758147 [15460.053012] .avg_idle : 1000000 [15460.053012] .ttwu_count : 922833 [15460.053012] .ttwu_local : 721258 [15460.053012] .bkl_count : 113 [15460.053012] [15460.053012] cfs_rq[0]:/ [15460.053012] .exec_clock : 565672.449837 [15460.053012] .MIN_vruntime : 0.000001 [15460.053012] .min_vruntime : 684253.393210 [15460.053012] .max_vruntime : 0.000001 [15460.053012] .spread : 0.000000 [15460.053012] .spread0 : 0.000000 [15460.053012] .nr_running : 1 [15460.053012] .load : 1024 [15460.053012] .nr_spread_over : 2 [15460.053012] .shares : 0 [15460.053012] [15460.053012] rt_rq[0]:/ [15460.053012] .rt_nr_running : 0 [15460.053012] .rt_throttled : 0 [15460.053012] .rt_time : 0.000000 [15460.053012] .rt_runtime : 950.000000 [15460.053012] [15460.053012] runnable tasks: [15460.053012] task PID tree-key switches prio exec-runtime sum-exec sum-sleep [15460.053012] ---------------------------------------------------------------------------------------------------------- [15460.053012] R bash 17674 684253.393210 448 120 684253.393210 168.337420 700111.995795 / [15460.053012] [15460.053012] cpu#1, 2194.944 MHz [15460.053012] .nr_running : 0 [15460.053012] .load : 0 [15460.053012] .nr_switches : 2781711 [15460.053012] .nr_load_updates : 585052 [15460.053012] .nr_uninterruptible : 0 [15460.053012] .next_balance : 3.790015 [15460.053012] .curr->pid : 0 [15460.053012] .clock : 15460053.425771 [15460.053012] .cpu_load[0] : 0 [15460.053012] .cpu_load[1] : 0 [15460.053012] .cpu_load[2] : 0 [15460.053012] .cpu_load[3] : 0 [15460.053012] .cpu_load[4] : 0 [15460.053012] .yld_count : 971 [15460.053012] .sched_switch : 0 [15460.053012] .sched_count : 2828076 [15460.053012] .sched_goidle : 1319436 [15460.053012] .avg_idle : 875273 [15460.053012] .ttwu_count : 1398861 [15460.053012] .ttwu_local : 1163642 [15460.053012] .bkl_count : 79 [15460.053012] [15460.053012] cfs_rq[1]:/ [15460.053012] .exec_clock : 415244.483606 [15460.053012] .MIN_vruntime : 0.000001 [15460.053012] .min_vruntime : 507085.016198 [15460.053012] .max_vruntime : 0.000001 [15460.053012] .spread : 0.000000 [15460.053012] .spread0 : -177168.377012 [15460.053012] .nr_running : 0 [15460.053012] .load : 0 [15460.053012] .nr_spread_over : 1 [15460.053012] .shares : 0 [15460.053012] [15460.053012] rt_rq[1]:/ [15460.053012] .rt_nr_running : 0 [15460.053012] .rt_throttled : 0 [15460.053012] .rt_time : 0.000000 [15460.053012] .rt_runtime : 950.000000 [15460.053012] [15460.053012] runnable tasks: [15460.053012] task PID tree-key switches prio exec-runtime sum-exec sum-sleep [15460.053012] ---------------------------------------------------------------------------------------------------------- [15460.053012] [15492.337181] SysRq : Show clockevent devices & pending hrtimers (no others) [15492.341016] Timer List Version: v0.5 [15492.341016] HRTIMER_MAX_CLOCK_BASES: 2 [15492.341016] now at 15492345437343 nsecs [15492.341016] [15492.341016] cpu: 0 [15492.341016] clock 0: [15492.341016] .base: c70049a4 [15492.341016] .index: 0 [15492.341016] .resolution: 1 nsecs [15492.341016] .get_time: ktime_get_real [15492.341016] .offset: 1297125938059809325 nsecs [15492.341016] active timers: [15492.341016] clock 1: [15492.341016] .base: c70049d0 [15492.341016] .index: 1 [15492.341016] .resolution: 1 nsecs [15492.341016] .get_time: ktime_get [15492.341016] .offset: 0 nsecs [15492.341016] active timers: [15492.341016] #0: <c7004a60>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0 [15492.341016] # expires at 15492340000000-15492340000000 nsecs [in -5437343 to -5437343 nsecs] [15492.341016] #1: <f5105ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, zypper/28960 [15492.341016] # expires at 15497197764475-15497202764474 nsecs [in 4852327132 to 4857327131 nsecs] [15492.341016] #2: <f6e09f40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, cron/884 [15492.341016] # expires at 15503084128363-15503084178363 nsecs [in 10738691020 to 10738741020 nsecs] [15492.341016] #3: <f4f19ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, winbindd/917 [15492.341016] # expires at 15510366264172-15510396264171 nsecs [in 18020826829 to 18050826828 nsecs] [15492.341016] #4: <f52bfef4>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rsyslogd/17711 [15492.341016] # expires at 15520060947543-15520060997543 nsecs [in 27715510200 to 27715560200 nsecs] [15492.341016] #5: <f4f37f40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, atd/885 [15492.341016] # expires at 18011893116083-18011893166083 nsecs [in 2519547678740 to 2519547728740 nsecs] [15492.341016] #6: <f4cc3ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, smbd/836 [15492.341016] # expires at 20009829520272-20009929520272 nsecs [in 4517484082929 to 4517584082929 nsecs] [15492.341016] .expires_next : 15492340000000 nsecs [15492.341016] .hres_active : 1 [15492.341016] .nr_events : 641821 [15492.341016] .nr_retries : 26332 [15492.341016] .nr_hangs : 0 [15492.341016] .max_hang_time : 0 nsecs [15492.341016] .nohz_mode : 2 [15492.341016] .idle_tick : 15492236000000 nsecs [15492.341016] .tick_stopped : 0 [15492.341016] .idle_jiffies : 3798058 [15492.341016] .idle_calls : 1096583 [15492.341016] .idle_sleeps : 330634 [15492.341016] .idle_entrytime : 15492232028728 nsecs [15492.341016] .idle_waketime : 15492232000843 nsecs [15492.341016] .idle_exittime : 15492337016034 nsecs [15492.341016] .idle_sleeptime : 14901605968046 nsecs [15492.341016] .last_jiffies : 3798058 [15492.341016] .next_jiffies : 3798120 [15492.341016] .idle_expires : 15492480000000 nsecs [15492.341016] jiffies: 3798086 [15492.341016] [15492.341016] cpu: 1 [15492.341016] clock 0: [15492.341016] .base: c71049a4 [15492.341016] .index: 0 [15492.341016] .resolution: 1 nsecs [15492.341016] .get_time: ktime_get_real [15492.341016] .offset: 1297125938059809325 nsecs [15492.341016] active timers: [15492.341016] clock 1: [15492.341016] .base: c71049d0 [15492.341016] .index: 1 [15492.341016] .resolution: 1 nsecs [15492.341016] .get_time: ktime_get [15492.341016] .offset: 0 nsecs [15492.341016] active timers: [15492.341016] #0: <c7104a60>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0 [15492.341016] # expires at 15492349000000-15492349000000 nsecs [in 3562657 to 3562657 nsecs] [15492.341016] #1: <f4c8bad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, apache2/947 [15492.341016] # expires at 15492556578781-15492557578780 nsecs [in 211141438 to 212141437 nsecs] [15492.341016] #2: <f5359ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, smbd/1140 [15492.341016] # expires at 15496084626915-15496121504563 nsecs [in 3739189572 to 3776067220 nsecs] [15492.341016] #3: <f4f3bad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rsyslogd/806 [15492.341016] # expires at 15507004032991-15507034032990 nsecs [in 14658595648 to 14688595647 nsecs] [15492.341016] #4: <f4d29ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, smbd/796 [15492.341016] # expires at 20130936331799-20131036331799 nsecs [in 4638590894456 to 4638690894456 nsecs] [15492.341016] .expires_next : 15492349000000 nsecs [15492.341016] .hres_active : 1 [15492.341016] .nr_events : 793193 [15492.341016] .nr_retries : 26862 [15492.341016] .nr_hangs : 0 [15492.341016] .max_hang_time : 0 nsecs [15492.341016] .nohz_mode : 2 [15492.341016] .idle_tick : 15492253000000 nsecs [15492.341016] .tick_stopped : 0 [15492.341016] .idle_jiffies : 3798063 [15492.341016] .idle_calls : 2433134 [15492.341016] .idle_sleeps : 913836 [15492.341016] .idle_entrytime : 15492345003341 nsecs [15492.341016] .idle_waketime : 15492332763723 nsecs [15492.341016] .idle_exittime : 15492332774252 nsecs [15492.341016] .idle_sleeptime : 15052885462990 nsecs [15492.341016] .last_jiffies : 3798086 [15492.341016] .next_jiffies : 3798097 [15492.341016] .idle_expires : 15492444000000 nsecs [15492.341016] jiffies: 3798086 [15492.341016] [15492.341016] [15492.341016] Tick Device: mode: 1 [15492.341016] Broadcast device [15492.341016] Clock Event Device: hpet [15492.341016] max_delta_ns: 2147483647 [15492.341016] min_delta_ns: 5000 [15492.341016] mult: 61496114 [15492.341016] shift: 32 [15492.341016] mode: 3 [15492.341016] next_event: 9223372036854775807 nsecs [15492.341016] set_next_event: hpet_legacy_next_event [15492.341016] set_mode: hpet_legacy_set_mode [15492.341016] event_handler: tick_handle_oneshot_broadcast [15492.341016] tick_broadcast_mask: 00000000 [15492.341016] tick_broadcast_oneshot_mask: 00000000 [15492.341016] [15492.341016] [15492.341016] Tick Device: mode: 1 [15492.341016] Per CPU device: 0 [15492.341016] Clock Event Device: lapic [15492.341016] max_delta_ns: 672820093 [15492.341016] min_delta_ns: 1203 [15492.341016] mult: 53548925 [15492.341016] shift: 32 [15492.341016] mode: 3 [15492.341016] next_event: 15492340000000 nsecs [15492.341016] set_next_event: lapic_next_event [15492.341016] set_mode: lapic_timer_setup [15492.341016] event_handler: hrtimer_interrupt [15492.341016] [15492.341016] Tick Device: mode: 1 [15492.341016] Per CPU device: 1 [15492.341016] Clock Event Device: lapic [15492.341016] max_delta_ns: 672820093 [15492.341016] min_delta_ns: 1203 [15492.341016] mult: 53548925 [15492.341016] shift: 32 [15492.341016] mode: 3 [15492.341016] next_event: 15492349000000 nsecs [15492.341016] set_next_event: lapic_next_event [15492.341016] set_mode: lapic_timer_setup [15492.341016] event_handler: hrtimer_interrupt [15492.341016] [15676.361191] SysRq : Show Memory [15676.365011] Mem-Info: [15676.365011] DMA per-cpu: [15676.365011] CPU 0: hi: 0, btch: 1 usd: 0 [15676.365011] CPU 1: hi: 0, btch: 1 usd: 0 [15676.365011] Normal per-cpu: [15676.365011] CPU 0: hi: 186, btch: 31 usd: 73 [15676.365011] CPU 1: hi: 186, btch: 31 usd: 176 [15676.365011] HighMem per-cpu: [15676.365011] CPU 0: hi: 186, btch: 31 usd: 76 [15676.365011] CPU 1: hi: 186, btch: 31 usd: 99 [15676.365011] active_anon:5431 inactive_anon:7392 isolated_anon:0 [15676.365011] active_file:199148 inactive_file:241880 isolated_file:0 [15676.365011] unevictable:11 dirty:0 writeback:0 unstable:0 [15676.365011] free:13441 slab_reclaimable:21971 slab_unreclaimable:2072 [15676.365011] mapped:4822 shmem:254 pagetables:345 bounce:0 [15676.365011] DMA free:8100kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:20kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15804kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes [15676.365011] lowmem_reserve[]: 0 867 2005 2005 [15676.365011] Normal free:42564kB min:3732kB low:4664kB high:5596kB active_anon:0kB inactive_anon:488kB active_file:294868kB inactive_file:354120kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:887976kB mlocked:0kB dirty:0kB writeback:0kB mapped:720kB shmem:0kB slab_reclaimable:87884kB slab_unreclaimable:8280kB kernel_stack:1248kB pagetables:28kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no [15676.365011] lowmem_reserve[]: 0 0 9106 9106 [15676.365011] HighMem free:3100kB min:512kB low:1736kB high:2960kB active_anon:21724kB inactive_anon:29080kB active_file:501724kB inactive_file:613380kB unevictable:44kB isolated(anon):0kB isolated(file):0kB present:1165660kB mlocked:0kB dirty:0kB writeback:0kB mapped:18568kB shmem:1016kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:1352kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no [15676.365011] lowmem_reserve[]: 0 0 0 0 [15676.365011] DMA: 1*4kB 6*8kB 5*16kB 5*32kB 4*64kB 3*128kB 2*256kB 3*512kB 1*1024kB 2*2048kB 0*4096kB = 8100kB [15676.365011] Normal: 535*4kB 303*8kB 563*16kB 326*32kB 116*64kB 33*128kB 3*256kB 0*512kB 0*1024kB 1*2048kB 1*4096kB = 42564kB [15676.365011] HighMem: 19*4kB 26*8kB 30*16kB 17*32kB 10*64kB 5*128kB 2*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3100kB [15676.365011] 441294 total pagecache pages [15676.365011] 0 pages in swap cache [15676.365011] Swap cache stats: add 0, delete 0, find 0/0 [15676.365011] Free swap = 0kB [15676.365011] Total swap = 0kB [15676.365011] 521532 pages RAM [15676.365011] 293710 pages HighMem [15676.365011] 25301 pages reserved [15676.365011] 410815 pages shared [15676.365011] 81402 pages non-shared # cat /proc/17496/status Name: sh State: D (disk sleep) Tgid: 17496 Pid: 17496 PPid: 17470 TracerPid: 0 Uid: 0 0 0 0 Gid: 0 0 0 0 FDSize: 256 Groups: 0 VmPeak: 3008 kB VmSize: 3008 kB VmLck: 0 kB VmHWM: 400 kB VmRSS: 400 kB VmData: 196 kB VmStk: 88 kB VmExe: 580 kB VmLib: 2064 kB VmPTE: 20 kB Threads: 1 SigQ: 2/16382 SigPnd: 0000000000000000 ShdPnd: 0000000000000002 SigBlk: 0000000000000000 SigIgn: 0000000000000000 SigCgt: 0000000000010002 CapInh: 0000000000000000 CapPrm: ffffffffffffffff CapEff: ffffffffffffffff CapBnd: ffffffffffffffff Cpus_allowed: 3 Cpus_allowed_list: 0-1 Mems_allowed: 1 Mems_allowed_list: 0 voluntary_ctxt_switches: 1 nonvoluntary_ctxt_switches: 0 # cat /proc/version Linux version 2.6.32-28-generic-pae (buildd@palmer) (gcc version 4.4.3 (Ubuntu 4.4.3-4ubuntu5) ) #55-Ubuntu SMP Mon Jan 10 22:34:08 UTC 2011 # cat /proc/cmdline BOOT_IMAGE=/boot/vmlinuz-2.6.32-28-generic-pae root=UUID=59b657e8-f757-4b9b-807f-56541a7cefa6 ro crashkernel=384M-2G:64M,2G-:128M quiet splash ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-02-08 5:26 [2.6.32 ubuntu] I/O hang at start_this_handle Tetsuo Handa @ 2011-02-15 15:16 ` Jan Kara 2011-02-15 21:52 ` Tetsuo Handa 0 siblings, 1 reply; 11+ messages in thread From: Jan Kara @ 2011-02-15 15:16 UTC (permalink / raw) To: Tetsuo Handa; +Cc: linux-fsdevel, linux-mm On Tue 08-02-11 14:26:00, Tetsuo Handa wrote: > I got below hangup. Is this known problem? > > Installing: grub-0.97-173.6 [91%] > > # dmesg > [14280.252030] INFO: task sh:17496 blocked for more than 120 seconds. > [14280.252228] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [14280.252447] sh D 00000000 0 17496 17470 0x00000000 > [14280.252455] f6f8fcf8 00200082 c02084a3 00000000 00000000 c088e4c0 f6d39c24 c088e4c0 > [14280.252468] 15e72f78 00000ccd c088e4c0 c088e4c0 f6d39c24 c088e4c0 c088e4c0 f40c2a80 > [14280.252480] 15e50702 00000ccd f6d39980 f4d2b63c f4d2b600 00000000 f6f8fd54 c02c7ead > [14280.252492] Call Trace: > [14280.252503] [<c02084a3>] ? __slab_alloc+0x163/0x220 > [14280.252512] [<c02c7ead>] start_this_handle+0x22d/0x390 > [14280.252519] [<c016ff90>] ? autoremove_wake_function+0x0/0x50 > [14280.252525] [<c02c8188>] journal_start+0x98/0xd0 > [14280.252532] [<c027b06e>] ext3_journal_start_sb+0x2e/0x50 > [14280.252538] [<c0272f02>] ext3_dirty_inode+0x32/0x80 > [14280.252545] [<c0231c71>] __mark_inode_dirty+0x31/0x180 > [14280.252552] [<c022900a>] inode_setattr+0xaa/0x170 > [14280.252557] [<c0273091>] ext3_setattr+0x141/0x1f0 > [14280.252563] [<c0229213>] notify_change+0x143/0x340 > [14280.252571] [<c02122d2>] do_truncate+0x62/0x90 > [14280.252578] [<c03018ea>] ? security_path_truncate+0x3a/0x50 > [14280.252584] [<c021c710>] may_open+0x1d0/0x200 > [14280.252591] [<c021f9fc>] do_filp_open+0xfc/0x990 > [14280.252597] [<c01efb74>] ? do_wp_page+0x104/0x910 > [14280.252605] [<c02111d5>] do_sys_open+0x55/0x160 > [14280.252611] [<c021134e>] sys_open+0x2e/0x40 > [14280.252617] [<c01096c3>] sysenter_do_call+0x12/0x28 Ext3 looks innocent here. That is a standard call path for open(.., O_TRUNC). But apparently something broke in SLUB allocator. Adding proper list to CC... > [14400.252032] INFO: task sh:17496 blocked for more than 120 seconds. > [14400.252201] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [14400.252429] sh D 00000000 0 17496 17470 0x00000000 > [14400.252437] f6f8fcf8 00200082 c02084a3 00000000 00000000 c088e4c0 f6d39c24 c088e4c0 > [14400.252450] 15e72f78 00000ccd c088e4c0 c088e4c0 f6d39c24 c088e4c0 c088e4c0 f40c2a80 > [14400.252461] 15e50702 00000ccd f6d39980 f4d2b63c f4d2b600 00000000 f6f8fd54 c02c7ead > [14400.252473] Call Trace: > [14400.252484] [<c02084a3>] ? __slab_alloc+0x163/0x220 > [14400.252492] [<c02c7ead>] start_this_handle+0x22d/0x390 > [14400.252500] [<c016ff90>] ? autoremove_wake_function+0x0/0x50 > [14400.252506] [<c02c8188>] journal_start+0x98/0xd0 > [14400.252512] [<c027b06e>] ext3_journal_start_sb+0x2e/0x50 > [14400.252518] [<c0272f02>] ext3_dirty_inode+0x32/0x80 > [14400.252525] [<c0231c71>] __mark_inode_dirty+0x31/0x180 > [14400.252532] [<c022900a>] inode_setattr+0xaa/0x170 > [14400.252537] [<c0273091>] ext3_setattr+0x141/0x1f0 > [14400.252543] [<c0229213>] notify_change+0x143/0x340 > [14400.252550] [<c02122d2>] do_truncate+0x62/0x90 > [14400.252557] [<c03018ea>] ? security_path_truncate+0x3a/0x50 > [14400.252564] [<c021c710>] may_open+0x1d0/0x200 > [14400.252570] [<c021f9fc>] do_filp_open+0xfc/0x990 > [14400.252577] [<c01efb74>] ? do_wp_page+0x104/0x910 > [14400.252584] [<c02111d5>] do_sys_open+0x55/0x160 > [14400.252590] [<c021134e>] sys_open+0x2e/0x40 > [14400.252596] [<c01096c3>] sysenter_do_call+0x12/0x28 > > CPU usage is almost 0%. Below is some sysrq info. > > [15460.045190] SysRq : Show Blocked State > [15460.053012] task PC stack pid father > [15460.053012] sh D 00000000 0 17496 17470 0x00000000 > [15460.053012] f6f8fcf8 00200082 c02084a3 00000000 00000000 c088e4c0 f6d39c24 c088e4c0 > [15460.053012] 15e72f78 00000ccd c088e4c0 c088e4c0 f6d39c24 c088e4c0 c088e4c0 f40c2a80 > [15460.053012] 15e50702 00000ccd f6d39980 f4d2b63c f4d2b600 00000000 f6f8fd54 c02c7ead > [15460.053012] Call Trace: > [15460.053012] [<c02084a3>] ? __slab_alloc+0x163/0x220 > [15460.053012] [<c02c7ead>] start_this_handle+0x22d/0x390 > [15460.053012] [<c016ff90>] ? autoremove_wake_function+0x0/0x50 > [15460.053012] [<c02c8188>] journal_start+0x98/0xd0 > [15460.053012] [<c027b06e>] ext3_journal_start_sb+0x2e/0x50 > [15460.053012] [<c0272f02>] ext3_dirty_inode+0x32/0x80 > [15460.053012] [<c0231c71>] __mark_inode_dirty+0x31/0x180 > [15460.053012] [<c022900a>] inode_setattr+0xaa/0x170 > [15460.053012] [<c0273091>] ext3_setattr+0x141/0x1f0 > [15460.053012] [<c0229213>] notify_change+0x143/0x340 > [15460.053012] [<c02122d2>] do_truncate+0x62/0x90 > [15460.053012] [<c03018ea>] ? security_path_truncate+0x3a/0x50 > [15460.053012] [<c021c710>] may_open+0x1d0/0x200 > [15460.053012] [<c021f9fc>] do_filp_open+0xfc/0x990 > [15460.053012] [<c01efb74>] ? do_wp_page+0x104/0x910 > [15460.053012] [<c02111d5>] do_sys_open+0x55/0x160 > [15460.053012] [<c021134e>] sys_open+0x2e/0x40 > [15460.053012] [<c01096c3>] sysenter_do_call+0x12/0x28 > [15460.053012] Sched Debug Version: v0.09, 2.6.32-28-generic-pae #55-Ubuntu > [15460.053012] now at 15460053.551044 msecs > [15460.053012] .jiffies : 3790013 > [15460.053012] .sysctl_sched_latency : 10.000000 > [15460.053012] .sysctl_sched_min_granularity : 2.000000 > [15460.053012] .sysctl_sched_wakeup_granularity : 2.000000 > [15460.053012] .sysctl_sched_child_runs_first : 0.000000 > [15460.053012] .sysctl_sched_features : 15834235 > [15460.053012] > [15460.053012] cpu#0, 2194.944 MHz > [15460.053012] .nr_running : 1 > [15460.053012] .load : 1024 > [15460.053012] .nr_switches : 1773885 > [15460.053012] .nr_load_updates : 494855 > [15460.053012] .nr_uninterruptible : 1 > [15460.053012] .next_balance : 3.789648 > [15460.053012] .curr->pid : 17674 > [15460.053012] .clock : 15460045.031387 > [15460.053012] .cpu_load[0] : 0 > [15460.053012] .cpu_load[1] : 0 > [15460.053012] .cpu_load[2] : 0 > [15460.053012] .cpu_load[3] : 0 > [15460.053012] .cpu_load[4] : 0 > [15460.053012] .yld_count : 1006 > [15460.053012] .sched_switch : 0 > [15460.053012] .sched_count : 1819077 > [15460.053012] .sched_goidle : 758147 > [15460.053012] .avg_idle : 1000000 > [15460.053012] .ttwu_count : 922833 > [15460.053012] .ttwu_local : 721258 > [15460.053012] .bkl_count : 113 > [15460.053012] > [15460.053012] cfs_rq[0]:/ > [15460.053012] .exec_clock : 565672.449837 > [15460.053012] .MIN_vruntime : 0.000001 > [15460.053012] .min_vruntime : 684253.393210 > [15460.053012] .max_vruntime : 0.000001 > [15460.053012] .spread : 0.000000 > [15460.053012] .spread0 : 0.000000 > [15460.053012] .nr_running : 1 > [15460.053012] .load : 1024 > [15460.053012] .nr_spread_over : 2 > [15460.053012] .shares : 0 > [15460.053012] > [15460.053012] rt_rq[0]:/ > [15460.053012] .rt_nr_running : 0 > [15460.053012] .rt_throttled : 0 > [15460.053012] .rt_time : 0.000000 > [15460.053012] .rt_runtime : 950.000000 > [15460.053012] > [15460.053012] runnable tasks: > [15460.053012] task PID tree-key switches prio exec-runtime sum-exec sum-sleep > [15460.053012] ---------------------------------------------------------------------------------------------------------- > [15460.053012] R bash 17674 684253.393210 448 120 684253.393210 168.337420 700111.995795 / > [15460.053012] > [15460.053012] cpu#1, 2194.944 MHz > [15460.053012] .nr_running : 0 > [15460.053012] .load : 0 > [15460.053012] .nr_switches : 2781711 > [15460.053012] .nr_load_updates : 585052 > [15460.053012] .nr_uninterruptible : 0 > [15460.053012] .next_balance : 3.790015 > [15460.053012] .curr->pid : 0 > [15460.053012] .clock : 15460053.425771 > [15460.053012] .cpu_load[0] : 0 > [15460.053012] .cpu_load[1] : 0 > [15460.053012] .cpu_load[2] : 0 > [15460.053012] .cpu_load[3] : 0 > [15460.053012] .cpu_load[4] : 0 > [15460.053012] .yld_count : 971 > [15460.053012] .sched_switch : 0 > [15460.053012] .sched_count : 2828076 > [15460.053012] .sched_goidle : 1319436 > [15460.053012] .avg_idle : 875273 > [15460.053012] .ttwu_count : 1398861 > [15460.053012] .ttwu_local : 1163642 > [15460.053012] .bkl_count : 79 > [15460.053012] > [15460.053012] cfs_rq[1]:/ > [15460.053012] .exec_clock : 415244.483606 > [15460.053012] .MIN_vruntime : 0.000001 > [15460.053012] .min_vruntime : 507085.016198 > [15460.053012] .max_vruntime : 0.000001 > [15460.053012] .spread : 0.000000 > [15460.053012] .spread0 : -177168.377012 > [15460.053012] .nr_running : 0 > [15460.053012] .load : 0 > [15460.053012] .nr_spread_over : 1 > [15460.053012] .shares : 0 > [15460.053012] > [15460.053012] rt_rq[1]:/ > [15460.053012] .rt_nr_running : 0 > [15460.053012] .rt_throttled : 0 > [15460.053012] .rt_time : 0.000000 > [15460.053012] .rt_runtime : 950.000000 > [15460.053012] > [15460.053012] runnable tasks: > [15460.053012] task PID tree-key switches prio exec-runtime sum-exec sum-sleep > [15460.053012] ---------------------------------------------------------------------------------------------------------- > [15460.053012] > > [15492.337181] SysRq : Show clockevent devices & pending hrtimers (no others) > [15492.341016] Timer List Version: v0.5 > [15492.341016] HRTIMER_MAX_CLOCK_BASES: 2 > [15492.341016] now at 15492345437343 nsecs > [15492.341016] > [15492.341016] cpu: 0 > [15492.341016] clock 0: > [15492.341016] .base: c70049a4 > [15492.341016] .index: 0 > [15492.341016] .resolution: 1 nsecs > [15492.341016] .get_time: ktime_get_real > [15492.341016] .offset: 1297125938059809325 nsecs > [15492.341016] active timers: > [15492.341016] clock 1: > [15492.341016] .base: c70049d0 > [15492.341016] .index: 1 > [15492.341016] .resolution: 1 nsecs > [15492.341016] .get_time: ktime_get > [15492.341016] .offset: 0 nsecs > [15492.341016] active timers: > [15492.341016] #0: <c7004a60>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0 > [15492.341016] # expires at 15492340000000-15492340000000 nsecs [in -5437343 to -5437343 nsecs] > [15492.341016] #1: <f5105ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, zypper/28960 > [15492.341016] # expires at 15497197764475-15497202764474 nsecs [in 4852327132 to 4857327131 nsecs] > [15492.341016] #2: <f6e09f40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, cron/884 > [15492.341016] # expires at 15503084128363-15503084178363 nsecs [in 10738691020 to 10738741020 nsecs] > [15492.341016] #3: <f4f19ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, winbindd/917 > [15492.341016] # expires at 15510366264172-15510396264171 nsecs [in 18020826829 to 18050826828 nsecs] > [15492.341016] #4: <f52bfef4>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rsyslogd/17711 > [15492.341016] # expires at 15520060947543-15520060997543 nsecs [in 27715510200 to 27715560200 nsecs] > [15492.341016] #5: <f4f37f40>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, atd/885 > [15492.341016] # expires at 18011893116083-18011893166083 nsecs [in 2519547678740 to 2519547728740 nsecs] > [15492.341016] #6: <f4cc3ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, smbd/836 > [15492.341016] # expires at 20009829520272-20009929520272 nsecs [in 4517484082929 to 4517584082929 nsecs] > [15492.341016] .expires_next : 15492340000000 nsecs > [15492.341016] .hres_active : 1 > [15492.341016] .nr_events : 641821 > [15492.341016] .nr_retries : 26332 > [15492.341016] .nr_hangs : 0 > [15492.341016] .max_hang_time : 0 nsecs > [15492.341016] .nohz_mode : 2 > [15492.341016] .idle_tick : 15492236000000 nsecs > [15492.341016] .tick_stopped : 0 > [15492.341016] .idle_jiffies : 3798058 > [15492.341016] .idle_calls : 1096583 > [15492.341016] .idle_sleeps : 330634 > [15492.341016] .idle_entrytime : 15492232028728 nsecs > [15492.341016] .idle_waketime : 15492232000843 nsecs > [15492.341016] .idle_exittime : 15492337016034 nsecs > [15492.341016] .idle_sleeptime : 14901605968046 nsecs > [15492.341016] .last_jiffies : 3798058 > [15492.341016] .next_jiffies : 3798120 > [15492.341016] .idle_expires : 15492480000000 nsecs > [15492.341016] jiffies: 3798086 > [15492.341016] > [15492.341016] cpu: 1 > [15492.341016] clock 0: > [15492.341016] .base: c71049a4 > [15492.341016] .index: 0 > [15492.341016] .resolution: 1 nsecs > [15492.341016] .get_time: ktime_get_real > [15492.341016] .offset: 1297125938059809325 nsecs > [15492.341016] active timers: > [15492.341016] clock 1: > [15492.341016] .base: c71049d0 > [15492.341016] .index: 1 > [15492.341016] .resolution: 1 nsecs > [15492.341016] .get_time: ktime_get > [15492.341016] .offset: 0 nsecs > [15492.341016] active timers: > [15492.341016] #0: <c7104a60>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0 > [15492.341016] # expires at 15492349000000-15492349000000 nsecs [in 3562657 to 3562657 nsecs] > [15492.341016] #1: <f4c8bad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, apache2/947 > [15492.341016] # expires at 15492556578781-15492557578780 nsecs [in 211141438 to 212141437 nsecs] > [15492.341016] #2: <f5359ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, smbd/1140 > [15492.341016] # expires at 15496084626915-15496121504563 nsecs [in 3739189572 to 3776067220 nsecs] > [15492.341016] #3: <f4f3bad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, rsyslogd/806 > [15492.341016] # expires at 15507004032991-15507034032990 nsecs [in 14658595648 to 14688595647 nsecs] > [15492.341016] #4: <f4d29ad8>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, smbd/796 > [15492.341016] # expires at 20130936331799-20131036331799 nsecs [in 4638590894456 to 4638690894456 nsecs] > [15492.341016] .expires_next : 15492349000000 nsecs > [15492.341016] .hres_active : 1 > [15492.341016] .nr_events : 793193 > [15492.341016] .nr_retries : 26862 > [15492.341016] .nr_hangs : 0 > [15492.341016] .max_hang_time : 0 nsecs > [15492.341016] .nohz_mode : 2 > [15492.341016] .idle_tick : 15492253000000 nsecs > [15492.341016] .tick_stopped : 0 > [15492.341016] .idle_jiffies : 3798063 > [15492.341016] .idle_calls : 2433134 > [15492.341016] .idle_sleeps : 913836 > [15492.341016] .idle_entrytime : 15492345003341 nsecs > [15492.341016] .idle_waketime : 15492332763723 nsecs > [15492.341016] .idle_exittime : 15492332774252 nsecs > [15492.341016] .idle_sleeptime : 15052885462990 nsecs > [15492.341016] .last_jiffies : 3798086 > [15492.341016] .next_jiffies : 3798097 > [15492.341016] .idle_expires : 15492444000000 nsecs > [15492.341016] jiffies: 3798086 > [15492.341016] > [15492.341016] > [15492.341016] Tick Device: mode: 1 > [15492.341016] Broadcast device > [15492.341016] Clock Event Device: hpet > [15492.341016] max_delta_ns: 2147483647 > [15492.341016] min_delta_ns: 5000 > [15492.341016] mult: 61496114 > [15492.341016] shift: 32 > [15492.341016] mode: 3 > [15492.341016] next_event: 9223372036854775807 nsecs > [15492.341016] set_next_event: hpet_legacy_next_event > [15492.341016] set_mode: hpet_legacy_set_mode > [15492.341016] event_handler: tick_handle_oneshot_broadcast > [15492.341016] tick_broadcast_mask: 00000000 > [15492.341016] tick_broadcast_oneshot_mask: 00000000 > [15492.341016] > [15492.341016] > [15492.341016] Tick Device: mode: 1 > [15492.341016] Per CPU device: 0 > [15492.341016] Clock Event Device: lapic > [15492.341016] max_delta_ns: 672820093 > [15492.341016] min_delta_ns: 1203 > [15492.341016] mult: 53548925 > [15492.341016] shift: 32 > [15492.341016] mode: 3 > [15492.341016] next_event: 15492340000000 nsecs > [15492.341016] set_next_event: lapic_next_event > [15492.341016] set_mode: lapic_timer_setup > [15492.341016] event_handler: hrtimer_interrupt > [15492.341016] > [15492.341016] Tick Device: mode: 1 > [15492.341016] Per CPU device: 1 > [15492.341016] Clock Event Device: lapic > [15492.341016] max_delta_ns: 672820093 > [15492.341016] min_delta_ns: 1203 > [15492.341016] mult: 53548925 > [15492.341016] shift: 32 > [15492.341016] mode: 3 > [15492.341016] next_event: 15492349000000 nsecs > [15492.341016] set_next_event: lapic_next_event > [15492.341016] set_mode: lapic_timer_setup > [15492.341016] event_handler: hrtimer_interrupt > [15492.341016] > > [15676.361191] SysRq : Show Memory > [15676.365011] Mem-Info: > [15676.365011] DMA per-cpu: > [15676.365011] CPU 0: hi: 0, btch: 1 usd: 0 > [15676.365011] CPU 1: hi: 0, btch: 1 usd: 0 > [15676.365011] Normal per-cpu: > [15676.365011] CPU 0: hi: 186, btch: 31 usd: 73 > [15676.365011] CPU 1: hi: 186, btch: 31 usd: 176 > [15676.365011] HighMem per-cpu: > [15676.365011] CPU 0: hi: 186, btch: 31 usd: 76 > [15676.365011] CPU 1: hi: 186, btch: 31 usd: 99 > [15676.365011] active_anon:5431 inactive_anon:7392 isolated_anon:0 > [15676.365011] active_file:199148 inactive_file:241880 isolated_file:0 > [15676.365011] unevictable:11 dirty:0 writeback:0 unstable:0 > [15676.365011] free:13441 slab_reclaimable:21971 slab_unreclaimable:2072 > [15676.365011] mapped:4822 shmem:254 pagetables:345 bounce:0 > [15676.365011] DMA free:8100kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:20kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15804kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes > [15676.365011] lowmem_reserve[]: 0 867 2005 2005 > [15676.365011] Normal free:42564kB min:3732kB low:4664kB high:5596kB active_anon:0kB inactive_anon:488kB active_file:294868kB inactive_file:354120kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:887976kB mlocked:0kB dirty:0kB writeback:0kB mapped:720kB shmem:0kB slab_reclaimable:87884kB slab_unreclaimable:8280kB kernel_stack:1248kB pagetables:28kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no > [15676.365011] lowmem_reserve[]: 0 0 9106 9106 > [15676.365011] HighMem free:3100kB min:512kB low:1736kB high:2960kB active_anon:21724kB inactive_anon:29080kB active_file:501724kB inactive_file:613380kB unevictable:44kB isolated(anon):0kB isolated(file):0kB present:1165660kB mlocked:0kB dirty:0kB writeback:0kB mapped:18568kB shmem:1016kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:1352kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no > [15676.365011] lowmem_reserve[]: 0 0 0 0 > [15676.365011] DMA: 1*4kB 6*8kB 5*16kB 5*32kB 4*64kB 3*128kB 2*256kB 3*512kB 1*1024kB 2*2048kB 0*4096kB = 8100kB > [15676.365011] Normal: 535*4kB 303*8kB 563*16kB 326*32kB 116*64kB 33*128kB 3*256kB 0*512kB 0*1024kB 1*2048kB 1*4096kB = 42564kB > [15676.365011] HighMem: 19*4kB 26*8kB 30*16kB 17*32kB 10*64kB 5*128kB 2*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3100kB > [15676.365011] 441294 total pagecache pages > [15676.365011] 0 pages in swap cache > [15676.365011] Swap cache stats: add 0, delete 0, find 0/0 > [15676.365011] Free swap = 0kB > [15676.365011] Total swap = 0kB > [15676.365011] 521532 pages RAM > [15676.365011] 293710 pages HighMem > [15676.365011] 25301 pages reserved > [15676.365011] 410815 pages shared > [15676.365011] 81402 pages non-shared > > # cat /proc/17496/status > Name: sh > State: D (disk sleep) > Tgid: 17496 > Pid: 17496 > PPid: 17470 > TracerPid: 0 > Uid: 0 0 0 0 > Gid: 0 0 0 0 > FDSize: 256 > Groups: 0 > VmPeak: 3008 kB > VmSize: 3008 kB > VmLck: 0 kB > VmHWM: 400 kB > VmRSS: 400 kB > VmData: 196 kB > VmStk: 88 kB > VmExe: 580 kB > VmLib: 2064 kB > VmPTE: 20 kB > Threads: 1 > SigQ: 2/16382 > SigPnd: 0000000000000000 > ShdPnd: 0000000000000002 > SigBlk: 0000000000000000 > SigIgn: 0000000000000000 > SigCgt: 0000000000010002 > CapInh: 0000000000000000 > CapPrm: ffffffffffffffff > CapEff: ffffffffffffffff > CapBnd: ffffffffffffffff > Cpus_allowed: 3 > Cpus_allowed_list: 0-1 > Mems_allowed: 1 > Mems_allowed_list: 0 > voluntary_ctxt_switches: 1 > nonvoluntary_ctxt_switches: 0 > > # cat /proc/version > Linux version 2.6.32-28-generic-pae (buildd@palmer) (gcc version 4.4.3 (Ubuntu 4.4.3-4ubuntu5) ) #55-Ubuntu SMP Mon Jan 10 22:34:08 UTC 2011 > > # cat /proc/cmdline > BOOT_IMAGE=/boot/vmlinuz-2.6.32-28-generic-pae root=UUID=59b657e8-f757-4b9b-807f-56541a7cefa6 ro crashkernel=384M-2G:64M,2G-:128M quiet splash Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR -- To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to majordomo@kvack.org. For more info on Linux MM, see: http://www.linux-mm.org/ . Fight unfair telecom internet charges in Canada: sign http://stopthemeter.ca/ Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a> ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-02-15 15:16 ` Jan Kara @ 2011-02-15 21:52 ` Tetsuo Handa 2011-02-16 15:53 ` Jan Kara 0 siblings, 1 reply; 11+ messages in thread From: Tetsuo Handa @ 2011-02-15 21:52 UTC (permalink / raw) To: jack; +Cc: linux-fsdevel, linux-mm Jan Kara wrote: > Ext3 looks innocent here. That is a standard call path for open(.., > O_TRUNC). But apparently something broke in SLUB allocator. Adding proper > list to CC... Thanks. Both fs/jbd/transaction.c and fs/jbd2/transaction.c provide start_this_handle() and I don't know which one was called. But if (!journal->j_running_transaction) { new_transaction = kzalloc(sizeof(*new_transaction), GFP_NOFS|__GFP_NOFAIL); if (!new_transaction) { ret = -ENOMEM; goto out; } } does kzalloc(GFP_NOFS|__GFP_NOFAIL) causes /proc/$PID/status to show State: D (disk sleep) line? I thought this is either if (transaction->t_state == T_LOCKED) { DEFINE_WAIT(wait); prepare_to_wait(&journal->j_wait_transaction_locked, &wait, TASK_UNINTERRUPTIBLE); spin_unlock(&journal->j_state_lock); schedule(); finish_wait(&journal->j_wait_transaction_locked, &wait); goto repeat; } or if (needed > journal->j_max_transaction_buffers) { /* * If the current transaction is already too large, then start * to commit it: we can then go back and attach this handle to * a new transaction. */ DEFINE_WAIT(wait); jbd_debug(2, "Handle %p starting new commit...\n", handle); spin_unlock(&transaction->t_handle_lock); prepare_to_wait(&journal->j_wait_transaction_locked, &wait, TASK_UNINTERRUPTIBLE); __jbd2_log_start_commit(journal, transaction->t_tid); spin_unlock(&journal->j_state_lock); schedule(); finish_wait(&journal->j_wait_transaction_locked, &wait); goto repeat; } within start_this_handle(). ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-02-15 21:52 ` Tetsuo Handa @ 2011-02-16 15:53 ` Jan Kara 2011-02-17 8:13 ` Tetsuo Handa 0 siblings, 1 reply; 11+ messages in thread From: Jan Kara @ 2011-02-16 15:53 UTC (permalink / raw) To: Tetsuo Handa; +Cc: jack, linux-fsdevel, linux-mm On Wed 16-02-11 06:52:55, Tetsuo Handa wrote: > Jan Kara wrote: > > Ext3 looks innocent here. That is a standard call path for open(.., > > O_TRUNC). But apparently something broke in SLUB allocator. Adding proper > > list to CC... > > Thanks. > > Both fs/jbd/transaction.c and fs/jbd2/transaction.c provide start_this_handle() > and I don't know which one was called. > > But > > if (!journal->j_running_transaction) { > new_transaction = kzalloc(sizeof(*new_transaction), > GFP_NOFS|__GFP_NOFAIL); > if (!new_transaction) { > ret = -ENOMEM; > goto out; > } > } > > does kzalloc(GFP_NOFS|__GFP_NOFAIL) causes /proc/$PID/status to show > > State: D (disk sleep) It could. State D does not mean "disk sleep" but "uninterruptible sleep". Lots of sleeps in kernel are in D state - for example waiting for all mutex locks, waiting for IO, etc. But looking at the trace again, you're probably right that we are actually waiting somewhere in start_this_handle() (in fs/jbd/transaction.c) and __slab_alloc() is just some relict on stack. You can verify this by looking at disassembly of start_this_handle() in your kernel and finding out where offset 0x22d is in the function... But in this case - does the process (sh) eventually resume or is it stuck forever? Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR -- To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to majordomo@kvack.org. For more info on Linux MM, see: http://www.linux-mm.org/ . Fight unfair telecom internet charges in Canada: sign http://stopthemeter.ca/ Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a> ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-02-16 15:53 ` Jan Kara @ 2011-02-17 8:13 ` Tetsuo Handa 2011-02-17 15:38 ` Jan Kara 0 siblings, 1 reply; 11+ messages in thread From: Tetsuo Handa @ 2011-02-17 8:13 UTC (permalink / raw) To: jack; +Cc: linux-fsdevel, linux-mm Jan Kara wrote: > You can verify this by looking at disassembly of start_this_handle() in your > kernel and finding out where offset 0x22d is in the function... I confirmed that the function [<c02c7ead>] start_this_handle+0x22d/0x390 is the one in fs/jbd/transaction.o . c02c7ea4: eb 07 jmp c02c7ead <start_this_handle+0x22d> c02c7ea6: 66 90 xchg %ax,%ax c02c7ea8: e8 93 a6 2e 00 call c05b2540 <schedule> c02c7ead: 89 d8 mov %ebx,%eax c02c7eaf: b9 02 00 00 00 mov $0x2,%ecx c02c7eb4: 8d 55 e0 lea -0x20(%ebp),%edx c02c7eb7: e8 d4 82 ea ff call c0170190 <prepare_to_wait> c02c7ebc: 8b 46 18 mov 0x18(%esi),%eax c02c7ebf: 85 c0 test %eax,%eax c02c7ec1: 75 e5 jne c02c7ea8 <start_this_handle+0x228> c02c7ec3: 8b 45 cc mov -0x34(%ebp),%eax c02c7ec6: 8d 55 e0 lea -0x20(%ebp),%edx c02c7ec9: e8 e2 81 ea ff call c01700b0 <finish_wait> c02c7ece: e9 08 fe ff ff jmp c02c7cdb <start_this_handle+0x5b> The location in that function is /* Wait on the journal's transaction barrier if necessary */ if (journal->j_barrier_count) { spin_unlock(&journal->j_state_lock); wait_event(journal->j_wait_transaction_locked, journal->j_barrier_count == 0); goto repeat; } . (Disassembly with mixed code attached at the bottom.) > But in this case - does the process (sh) eventually resume or is it stuck > forever? I waited for a few hours but the process did not resume. Thus, I gave up. Regards. ---------- 00000940 <start_this_handle>: * to begin. Attach the handle to a transaction and set up the * transaction's buffer credits. */ static int start_this_handle(journal_t *journal, handle_t *handle) { 940: 55 push %ebp 941: 89 e5 mov %esp,%ebp 943: 57 push %edi 944: 56 push %esi 945: 53 push %ebx 946: 83 ec 48 sub $0x48,%esp 949: e8 fc ff ff ff call 94a <start_this_handle+0xa> 94e: 89 c6 mov %eax,%esi 950: 89 55 c4 mov %edx,-0x3c(%ebp) transaction_t *transaction; int needed; int nblocks = handle->h_buffer_credits; 953: 8b 42 04 mov 0x4(%edx),%eax 956: 89 45 d8 mov %eax,-0x28(%ebp) transaction_t *new_transaction = NULL; int ret = 0; if (nblocks > journal->j_max_transaction_buffers) { 959: 8b 86 ec 00 00 00 mov 0xec(%esi),%eax 95f: 39 45 d8 cmp %eax,-0x28(%ebp) 962: 0f 8f ed 02 00 00 jg c55 <start_this_handle+0x315> /* * We need to hold j_state_lock until t_updates has been incremented, * for proper journal barrier handling */ spin_lock(&journal->j_state_lock); 968: 8d 46 14 lea 0x14(%esi),%eax } /* Wait on the journal's transaction barrier if necessary */ if (journal->j_barrier_count) { spin_unlock(&journal->j_state_lock); wait_event(journal->j_wait_transaction_locked, 96b: 8d 56 3c lea 0x3c(%esi),%edx spin_lock_init(&transaction->t_handle_lock); /* Set up the commit timer for the new transaction. */ journal->j_commit_timer.expires = round_jiffies_up(transaction->t_expires); add_timer(&journal->j_commit_timer); 96e: 8d 8e f4 00 00 00 lea 0xf4(%esi),%ecx /* * We need to hold j_state_lock until t_updates has been incremented, * for proper journal barrier handling */ spin_lock(&journal->j_state_lock); 974: 89 45 d4 mov %eax,-0x2c(%ebp) } /* Wait on the journal's transaction barrier if necessary */ if (journal->j_barrier_count) { spin_unlock(&journal->j_state_lock); wait_event(journal->j_wait_transaction_locked, 977: 89 55 cc mov %edx,-0x34(%ebp) 97a: 64 a1 00 00 00 00 mov %fs:0x0,%eax spin_lock_init(&transaction->t_handle_lock); /* Set up the commit timer for the new transaction. */ journal->j_commit_timer.expires = round_jiffies_up(transaction->t_expires); add_timer(&journal->j_commit_timer); 980: 89 4d d0 mov %ecx,-0x30(%ebp) 983: 89 45 c8 mov %eax,-0x38(%ebp) 986: 89 45 c0 mov %eax,-0x40(%ebp) ret = -ENOSPC; goto out; } alloc_transaction: if (!journal->j_running_transaction) { 989: 8b 7e 30 mov 0x30(%esi),%edi 98c: 85 ff test %edi,%edi 98e: 0f 84 85 02 00 00 je c19 <start_this_handle+0x2d9> 994: c7 45 dc 00 00 00 00 movl $0x0,-0x24(%ebp) /* * We need to hold j_state_lock until t_updates has been incremented, * for proper journal barrier handling */ spin_lock(&journal->j_state_lock); 99b: 8b 45 d4 mov -0x2c(%ebp),%eax 99e: e8 fc ff ff ff call 99f <start_this_handle+0x5f> * transactions. */ static inline int is_journal_aborted(journal_t *journal) { return journal->j_flags & JFS_ABORT; 9a3: 8b 06 mov (%esi),%eax repeat_locked: if (is_journal_aborted(journal) || 9a5: a8 02 test $0x2,%al 9a7: 74 66 je a0f <start_this_handle+0xcf> 9a9: e9 5a 01 00 00 jmp b08 <start_this_handle+0x1c8> 9ae: 66 90 xchg %ax,%ax /* * If the current transaction is locked down for commit, wait for the * lock to be released. */ if (transaction->t_state == T_LOCKED) { 9b0: 83 7b 08 01 cmpl $0x1,0x8(%ebx) 9b4: 0f 84 fe 00 00 00 je ab8 <start_this_handle+0x178> /* * If there is not enough space left in the log to write all potential * buffers requested by this operation, we need to stall pending a log * checkpoint to free some more log space. */ spin_lock(&transaction->t_handle_lock); 9ba: 8d 7b 3c lea 0x3c(%ebx),%edi 9bd: 89 f8 mov %edi,%eax 9bf: 90 nop 9c0: e8 fc ff ff ff call 9c1 <start_this_handle+0x81> needed = transaction->t_outstanding_credits + nblocks; 9c5: 8b 45 d8 mov -0x28(%ebp),%eax 9c8: 03 43 44 add 0x44(%ebx),%eax if (needed > journal->j_max_transaction_buffers) { 9cb: 3b 86 ec 00 00 00 cmp 0xec(%esi),%eax 9d1: 0f 8f c1 01 00 00 jg b98 <start_this_handle+0x258> * committing_transaction->t_outstanding_credits plus "enough" for * the log control blocks. * Also, this test is inconsitent with the matching one in * journal_extend(). */ if (__log_space_left(journal) < jbd_space_needed(journal)) { 9d7: 89 f0 mov %esi,%eax 9d9: e8 fc ff ff ff call 9da <start_this_handle+0x9a> * before a new transaction may be started. Must be called under j_state_lock. */ static inline int jbd_space_needed(journal_t *journal) { int nblocks = journal->j_max_transaction_buffers; if (journal->j_committing_transaction) 9de: 8b 4e 34 mov 0x34(%esi),%ecx * Return the minimum number of blocks which must be free in the journal * before a new transaction may be started. Must be called under j_state_lock. */ static inline int jbd_space_needed(journal_t *journal) { int nblocks = journal->j_max_transaction_buffers; 9e1: 8b 96 ec 00 00 00 mov 0xec(%esi),%edx if (journal->j_committing_transaction) 9e7: 85 c9 test %ecx,%ecx 9e9: 74 03 je 9ee <start_this_handle+0xae> nblocks += journal->j_committing_transaction-> 9eb: 03 51 44 add 0x44(%ecx),%edx 9ee: 39 d0 cmp %edx,%eax 9f0: 0f 8d ea 01 00 00 jge be0 <start_this_handle+0x2a0> 9f6: 89 f8 mov %edi,%eax 9f8: ff 15 14 00 00 00 call *0x14 jbd_debug(2, "Handle %p waiting for checkpoint...\n", handle); spin_unlock(&transaction->t_handle_lock); __log_wait_for_space(journal); 9fe: 89 f0 mov %esi,%eax a00: e8 fc ff ff ff call a01 <start_this_handle+0xc1> * transactions. */ static inline int is_journal_aborted(journal_t *journal) { return journal->j_flags & JFS_ABORT; a05: 8b 06 mov (%esi),%eax * We need to hold j_state_lock until t_updates has been incremented, * for proper journal barrier handling */ spin_lock(&journal->j_state_lock); repeat_locked: if (is_journal_aborted(journal) || a07: a8 02 test $0x2,%al a09: 0f 85 f9 00 00 00 jne b08 <start_this_handle+0x1c8> (journal->j_errno != 0 && !(journal->j_flags & JFS_ACK_ERR))) { a0f: 8b 5e 04 mov 0x4(%esi),%ebx a12: 85 db test %ebx,%ebx a14: 74 08 je a1e <start_this_handle+0xde> * We need to hold j_state_lock until t_updates has been incremented, * for proper journal barrier handling */ spin_lock(&journal->j_state_lock); repeat_locked: if (is_journal_aborted(journal) || a16: a8 04 test $0x4,%al a18: 0f 84 ea 00 00 00 je b08 <start_this_handle+0x1c8> ret = -EROFS; goto out; } /* Wait on the journal's transaction barrier if necessary */ if (journal->j_barrier_count) { a1e: 8b 4e 18 mov 0x18(%esi),%ecx a21: 85 c9 test %ecx,%ecx a23: 0f 85 07 01 00 00 jne b30 <start_this_handle+0x1f0> wait_event(journal->j_wait_transaction_locked, journal->j_barrier_count == 0); goto repeat; } if (!journal->j_running_transaction) { a29: 8b 5e 30 mov 0x30(%esi),%ebx a2c: 85 db test %ebx,%ebx a2e: 75 80 jne 9b0 <start_this_handle+0x70> if (!new_transaction) { a30: 8b 7d dc mov -0x24(%ebp),%edi a33: 85 ff test %edi,%edi a35: 0f 84 d0 01 00 00 je c0b <start_this_handle+0x2cb> */ static transaction_t * get_transaction(journal_t *journal, transaction_t *transaction) { transaction->t_journal = journal; a3b: 8b 55 dc mov -0x24(%ebp),%edx a3e: 89 32 mov %esi,(%edx) transaction->t_state = T_RUNNING; a40: c7 42 08 00 00 00 00 movl $0x0,0x8(%edx) transaction->t_start_time = ktime_get(); a47: e8 fc ff ff ff call a48 <start_this_handle+0x108> a4c: 8b 4d dc mov -0x24(%ebp),%ecx a4f: 89 41 54 mov %eax,0x54(%ecx) a52: 89 51 58 mov %edx,0x58(%ecx) transaction->t_tid = journal->j_transaction_sequence++; a55: 8b 86 cc 00 00 00 mov 0xcc(%esi),%eax a5b: 89 41 04 mov %eax,0x4(%ecx) a5e: 83 c0 01 add $0x1,%eax a61: 89 86 cc 00 00 00 mov %eax,0xcc(%esi) transaction->t_expires = jiffies + journal->j_commit_interval; a67: a1 00 00 00 00 mov 0x0,%eax a6c: 03 86 f0 00 00 00 add 0xf0(%esi),%eax spin_lock_init(&transaction->t_handle_lock); a72: c7 41 3c 00 00 00 00 movl $0x0,0x3c(%ecx) { transaction->t_journal = journal; transaction->t_state = T_RUNNING; transaction->t_start_time = ktime_get(); transaction->t_tid = journal->j_transaction_sequence++; transaction->t_expires = jiffies + journal->j_commit_interval; a79: 89 41 50 mov %eax,0x50(%ecx) spin_lock_init(&transaction->t_handle_lock); /* Set up the commit timer for the new transaction. */ journal->j_commit_timer.expires = round_jiffies_up(transaction->t_expires); a7c: e8 fc ff ff ff call a7d <start_this_handle+0x13d> transaction->t_tid = journal->j_transaction_sequence++; transaction->t_expires = jiffies + journal->j_commit_interval; spin_lock_init(&transaction->t_handle_lock); /* Set up the commit timer for the new transaction. */ journal->j_commit_timer.expires = a81: 89 86 fc 00 00 00 mov %eax,0xfc(%esi) round_jiffies_up(transaction->t_expires); add_timer(&journal->j_commit_timer); a87: 8b 45 d0 mov -0x30(%ebp),%eax a8a: e8 fc ff ff ff call a8b <start_this_handle+0x14b> J_ASSERT(journal->j_running_transaction == NULL); a8f: 8b 5e 30 mov 0x30(%esi),%ebx a92: 85 db test %ebx,%ebx a94: 0f 85 b7 01 00 00 jne c51 <start_this_handle+0x311> journal->j_running_transaction = transaction; a9a: 8b 45 dc mov -0x24(%ebp),%eax a9d: c7 45 dc 00 00 00 00 movl $0x0,-0x24(%ebp) aa4: 89 c3 mov %eax,%ebx aa6: 89 46 30 mov %eax,0x30(%esi) /* * If the current transaction is locked down for commit, wait for the * lock to be released. */ if (transaction->t_state == T_LOCKED) { aa9: 83 7b 08 01 cmpl $0x1,0x8(%ebx) aad: 0f 85 07 ff ff ff jne 9ba <start_this_handle+0x7a> ab3: 90 nop ab4: 8d 74 26 00 lea 0x0(%esi,%eiz,1),%esi DEFINE_WAIT(wait); ab8: 8b 55 c0 mov -0x40(%ebp),%edx abb: 8d 4d ec lea -0x14(%ebp),%ecx prepare_to_wait(&journal->j_wait_transaction_locked, abe: 8b 45 cc mov -0x34(%ebp),%eax /* * If the current transaction is locked down for commit, wait for the * lock to be released. */ if (transaction->t_state == T_LOCKED) { DEFINE_WAIT(wait); ac1: 89 4d ec mov %ecx,-0x14(%ebp) ac4: 89 4d f0 mov %ecx,-0x10(%ebp) prepare_to_wait(&journal->j_wait_transaction_locked, ac7: b9 02 00 00 00 mov $0x2,%ecx /* * If the current transaction is locked down for commit, wait for the * lock to be released. */ if (transaction->t_state == T_LOCKED) { DEFINE_WAIT(wait); acc: 89 55 e4 mov %edx,-0x1c(%ebp) prepare_to_wait(&journal->j_wait_transaction_locked, acf: 8d 55 e0 lea -0x20(%ebp),%edx /* * If the current transaction is locked down for commit, wait for the * lock to be released. */ if (transaction->t_state == T_LOCKED) { DEFINE_WAIT(wait); ad2: c7 45 e0 00 00 00 00 movl $0x0,-0x20(%ebp) ad9: c7 45 e8 00 00 00 00 movl $0x0,-0x18(%ebp) prepare_to_wait(&journal->j_wait_transaction_locked, ae0: e8 fc ff ff ff call ae1 <start_this_handle+0x1a1> ae5: 8b 45 d4 mov -0x2c(%ebp),%eax ae8: ff 15 14 00 00 00 call *0x14 spin_unlock(&transaction->t_handle_lock); prepare_to_wait(&journal->j_wait_transaction_locked, &wait, TASK_UNINTERRUPTIBLE); __log_start_commit(journal, transaction->t_tid); spin_unlock(&journal->j_state_lock); schedule(); aee: e8 fc ff ff ff call aef <start_this_handle+0x1af> finish_wait(&journal->j_wait_transaction_locked, &wait); af3: 8b 45 cc mov -0x34(%ebp),%eax af6: 8d 55 e0 lea -0x20(%ebp),%edx af9: e8 fc ff ff ff call afa <start_this_handle+0x1ba> afe: e9 98 fe ff ff jmp 99b <start_this_handle+0x5b> b03: 90 nop b04: 8d 74 26 00 lea 0x0(%esi,%eiz,1),%esi b08: 8b 45 d4 mov -0x2c(%ebp),%eax b0b: ff 15 14 00 00 00 call *0x14 b11: bb e2 ff ff ff mov $0xffffffe2,%ebx spin_unlock(&transaction->t_handle_lock); spin_unlock(&journal->j_state_lock); lock_map_acquire(&handle->h_lockdep_map); out: if (unlikely(new_transaction)) /* It's usually NULL */ b16: 8b 4d dc mov -0x24(%ebp),%ecx b19: 85 c9 test %ecx,%ecx b1b: 0f 85 66 01 00 00 jne c87 <start_this_handle+0x347> kfree(new_transaction); return ret; } b21: 83 c4 48 add $0x48,%esp b24: 89 d8 mov %ebx,%eax b26: 5b pop %ebx b27: 5e pop %esi b28: 5f pop %edi b29: 5d pop %ebp b2a: c3 ret b2b: 90 nop b2c: 8d 74 26 00 lea 0x0(%esi,%eiz,1),%esi b30: 8b 45 d4 mov -0x2c(%ebp),%eax b33: ff 15 14 00 00 00 call *0x14 } /* Wait on the journal's transaction barrier if necessary */ if (journal->j_barrier_count) { spin_unlock(&journal->j_state_lock); wait_event(journal->j_wait_transaction_locked, b39: 8b 56 18 mov 0x18(%esi),%edx b3c: 85 d2 test %edx,%edx b3e: 0f 84 57 fe ff ff je 99b <start_this_handle+0x5b> b44: 8b 55 c8 mov -0x38(%ebp),%edx b47: 8d 4d ec lea -0x14(%ebp),%ecx b4a: c7 45 e0 00 00 00 00 movl $0x0,-0x20(%ebp) b51: 8b 5d cc mov -0x34(%ebp),%ebx b54: c7 45 e8 00 00 00 00 movl $0x0,-0x18(%ebp) b5b: 89 4d ec mov %ecx,-0x14(%ebp) b5e: 89 55 e4 mov %edx,-0x1c(%ebp) b61: 89 4d f0 mov %ecx,-0x10(%ebp) b64: eb 07 jmp b6d <start_this_handle+0x22d> b66: 66 90 xchg %ax,%ax b68: e8 fc ff ff ff call b69 <start_this_handle+0x229> b6d: 89 d8 mov %ebx,%eax b6f: b9 02 00 00 00 mov $0x2,%ecx b74: 8d 55 e0 lea -0x20(%ebp),%edx b77: e8 fc ff ff ff call b78 <start_this_handle+0x238> b7c: 8b 46 18 mov 0x18(%esi),%eax b7f: 85 c0 test %eax,%eax b81: 75 e5 jne b68 <start_this_handle+0x228> prepare_to_wait(&journal->j_wait_transaction_locked, &wait, TASK_UNINTERRUPTIBLE); __log_start_commit(journal, transaction->t_tid); spin_unlock(&journal->j_state_lock); schedule(); finish_wait(&journal->j_wait_transaction_locked, &wait); b83: 8b 45 cc mov -0x34(%ebp),%eax b86: 8d 55 e0 lea -0x20(%ebp),%edx b89: e8 fc ff ff ff call b8a <start_this_handle+0x24a> b8e: e9 08 fe ff ff jmp 99b <start_this_handle+0x5b> b93: 90 nop b94: 8d 74 26 00 lea 0x0(%esi,%eiz,1),%esi /* * If the current transaction is already too large, then start * to commit it: we can then go back and attach this handle to * a new transaction. */ DEFINE_WAIT(wait); b98: 8b 55 c8 mov -0x38(%ebp),%edx b9b: 8d 4d ec lea -0x14(%ebp),%ecx b9e: 89 f8 mov %edi,%eax ba0: c7 45 e0 00 00 00 00 movl $0x0,-0x20(%ebp) ba7: c7 45 e8 00 00 00 00 movl $0x0,-0x18(%ebp) bae: 89 4d ec mov %ecx,-0x14(%ebp) bb1: 89 55 e4 mov %edx,-0x1c(%ebp) bb4: 89 4d f0 mov %ecx,-0x10(%ebp) bb7: ff 15 14 00 00 00 call *0x14 jbd_debug(2, "Handle %p starting new commit...\n", handle); spin_unlock(&transaction->t_handle_lock); prepare_to_wait(&journal->j_wait_transaction_locked, &wait, bbd: 8b 45 cc mov -0x34(%ebp),%eax bc0: 8d 55 e0 lea -0x20(%ebp),%edx bc3: b9 02 00 00 00 mov $0x2,%ecx bc8: e8 fc ff ff ff call bc9 <start_this_handle+0x289> TASK_UNINTERRUPTIBLE); __log_start_commit(journal, transaction->t_tid); bcd: 8b 53 04 mov 0x4(%ebx),%edx bd0: 89 f0 mov %esi,%eax bd2: e8 fc ff ff ff call bd3 <start_this_handle+0x293> bd7: e9 09 ff ff ff jmp ae5 <start_this_handle+0x1a5> bdc: 8d 74 26 00 lea 0x0(%esi,%eiz,1),%esi } /* OK, account for the buffers that this operation expects to * use and add the handle to the running transaction. */ handle->h_transaction = transaction; be0: 8b 55 c4 mov -0x3c(%ebp),%edx be3: 89 f8 mov %edi,%eax be5: 89 1a mov %ebx,(%edx) transaction->t_outstanding_credits += nblocks; be7: 8b 4d d8 mov -0x28(%ebp),%ecx bea: 01 4b 44 add %ecx,0x44(%ebx) transaction->t_updates++; bed: 83 43 40 01 addl $0x1,0x40(%ebx) transaction->t_handle_count++; bf1: 83 43 5c 01 addl $0x1,0x5c(%ebx) bf5: ff 15 14 00 00 00 call *0x14 bfb: 8b 45 d4 mov -0x2c(%ebp),%eax bfe: ff 15 14 00 00 00 call *0x14 c04: 31 db xor %ebx,%ebx c06: e9 0b ff ff ff jmp b16 <start_this_handle+0x1d6> c0b: 8b 45 d4 mov -0x2c(%ebp),%eax c0e: ff 15 14 00 00 00 call *0x14 c14: e9 70 fd ff ff jmp 989 <start_this_handle+0x49> extern void *kmem_cache_alloc_notrace(struct kmem_cache *s, gfp_t gfpflags); #else static __always_inline void * kmem_cache_alloc_notrace(struct kmem_cache *s, gfp_t gfpflags) { return kmem_cache_alloc(s, gfpflags); c19: ba 50 88 00 00 mov $0x8850,%edx c1e: b8 7c 04 00 00 mov $0x47c,%eax c23: e8 fc ff ff ff call c24 <start_this_handle+0x2e4> if (!s) return ZERO_SIZE_PTR; ret = kmem_cache_alloc_notrace(s, flags); trace_kmalloc(_THIS_IP_, ret, size, s->size, flags); c28: 8b 15 80 04 00 00 mov 0x480,%edx {(unsigned long)__GFP_THISNODE, "GFP_THISNODE"}, \ {(unsigned long)__GFP_RECLAIMABLE, "GFP_RECLAIMABLE"}, \ {(unsigned long)__GFP_MOVABLE, "GFP_MOVABLE"} \ ) : "GFP_NOWAIT" TRACE_EVENT(kmalloc, c2e: 83 3d 04 00 00 00 00 cmpl $0x0,0x4 c35: 89 55 bc mov %edx,-0x44(%ebp) extern void *kmem_cache_alloc_notrace(struct kmem_cache *s, gfp_t gfpflags); #else static __always_inline void * kmem_cache_alloc_notrace(struct kmem_cache *s, gfp_t gfpflags) { return kmem_cache_alloc(s, gfpflags); c38: 89 45 dc mov %eax,-0x24(%ebp) c3b: 75 58 jne c95 <start_this_handle+0x355> alloc_transaction: if (!journal->j_running_transaction) { new_transaction = kzalloc(sizeof(*new_transaction), GFP_NOFS|__GFP_NOFAIL); if (!new_transaction) { c3d: 83 7d dc 00 cmpl $0x0,-0x24(%ebp) c41: 0f 85 54 fd ff ff jne 99b <start_this_handle+0x5b> spin_unlock(&journal->j_state_lock); lock_map_acquire(&handle->h_lockdep_map); out: if (unlikely(new_transaction)) /* It's usually NULL */ kfree(new_transaction); c47: bb f4 ff ff ff mov $0xfffffff4,%ebx c4c: e9 d0 fe ff ff jmp b21 <start_this_handle+0x1e1> /* Set up the commit timer for the new transaction. */ journal->j_commit_timer.expires = round_jiffies_up(transaction->t_expires); add_timer(&journal->j_commit_timer); J_ASSERT(journal->j_running_transaction == NULL); c51: 0f 0b ud2a c53: eb fe jmp c53 <start_this_handle+0x313> int nblocks = handle->h_buffer_credits; transaction_t *new_transaction = NULL; int ret = 0; if (nblocks > journal->j_max_transaction_buffers) { printk(KERN_ERR "JBD: %s wants too many credits (%d > %d)\n", c55: 8b 4d d8 mov -0x28(%ebp),%ecx c58: bb e4 ff ff ff mov $0xffffffe4,%ebx c5d: 64 8b 15 00 00 00 00 mov %fs:0x0,%edx c64: 89 44 24 0c mov %eax,0xc(%esp) c68: 8d 82 0c 03 00 00 lea 0x30c(%edx),%eax c6e: 89 44 24 04 mov %eax,0x4(%esp) c72: 89 4c 24 08 mov %ecx,0x8(%esp) c76: c7 04 24 84 00 00 00 movl $0x84,(%esp) c7d: e8 fc ff ff ff call c7e <start_this_handle+0x33e> current->comm, nblocks, journal->j_max_transaction_buffers); ret = -ENOSPC; goto out; c82: e9 9a fe ff ff jmp b21 <start_this_handle+0x1e1> spin_unlock(&journal->j_state_lock); lock_map_acquire(&handle->h_lockdep_map); out: if (unlikely(new_transaction)) /* It's usually NULL */ kfree(new_transaction); c87: 8b 45 dc mov -0x24(%ebp),%eax c8a: e8 fc ff ff ff call c8b <start_this_handle+0x34b> c8f: 90 nop c90: e9 8c fe ff ff jmp b21 <start_this_handle+0x1e1> c95: 8b 1d 10 00 00 00 mov 0x10,%ebx c9b: 85 db test %ebx,%ebx c9d: 74 9e je c3d <start_this_handle+0x2fd> c9f: 8b 3b mov (%ebx),%edi ca1: 8b 4d bc mov -0x44(%ebp),%ecx ca4: 83 c3 04 add $0x4,%ebx ca7: b8 19 0c 00 00 mov $0xc19,%eax cac: 8b 55 dc mov -0x24(%ebp),%edx caf: c7 44 24 04 50 88 00 movl $0x8850,0x4(%esp) cb6: 00 cb7: 89 0c 24 mov %ecx,(%esp) cba: b9 64 00 00 00 mov $0x64,%ecx cbf: ff d7 call *%edi cc1: 8b 3b mov (%ebx),%edi cc3: 85 ff test %edi,%edi cc5: 75 da jne ca1 <start_this_handle+0x361> cc7: e9 71 ff ff ff jmp c3d <start_this_handle+0x2fd> ccc: 8d 74 26 00 lea 0x0(%esi,%eiz,1),%esi -- To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to majordomo@kvack.org. For more info on Linux MM, see: http://www.linux-mm.org/ . Fight unfair telecom internet charges in Canada: sign http://stopthemeter.ca/ Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a> ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-02-17 8:13 ` Tetsuo Handa @ 2011-02-17 15:38 ` Jan Kara 2011-04-08 14:38 ` Tetsuo Handa 0 siblings, 1 reply; 11+ messages in thread From: Jan Kara @ 2011-02-17 15:38 UTC (permalink / raw) To: Tetsuo Handa; +Cc: jack, linux-fsdevel, linux-mm Hello, On Thu 17-02-11 17:13:43, Tetsuo Handa wrote: > Jan Kara wrote: > > You can verify this by looking at disassembly of start_this_handle() in your > > kernel and finding out where offset 0x22d is in the function... > > I confirmed that the function > > [<c02c7ead>] start_this_handle+0x22d/0x390 > > is the one in fs/jbd/transaction.o . > > c02c7ea4: eb 07 jmp c02c7ead <start_this_handle+0x22d> > c02c7ea6: 66 90 xchg %ax,%ax > c02c7ea8: e8 93 a6 2e 00 call c05b2540 <schedule> > c02c7ead: 89 d8 mov %ebx,%eax > c02c7eaf: b9 02 00 00 00 mov $0x2,%ecx > c02c7eb4: 8d 55 e0 lea -0x20(%ebp),%edx > c02c7eb7: e8 d4 82 ea ff call c0170190 <prepare_to_wait> > c02c7ebc: 8b 46 18 mov 0x18(%esi),%eax > c02c7ebf: 85 c0 test %eax,%eax > c02c7ec1: 75 e5 jne c02c7ea8 <start_this_handle+0x228> > c02c7ec3: 8b 45 cc mov -0x34(%ebp),%eax > c02c7ec6: 8d 55 e0 lea -0x20(%ebp),%edx > c02c7ec9: e8 e2 81 ea ff call c01700b0 <finish_wait> > c02c7ece: e9 08 fe ff ff jmp c02c7cdb <start_this_handle+0x5b> > > The location in that function is > > /* Wait on the journal's transaction barrier if necessary */ > if (journal->j_barrier_count) { > spin_unlock(&journal->j_state_lock); > wait_event(journal->j_wait_transaction_locked, > journal->j_barrier_count == 0); > goto repeat; > } > > . (Disassembly with mixed code attached at the bottom.) Great, thanks for analysis. > > But in this case - does the process (sh) eventually resume or is it stuck > > forever? > > I waited for a few hours but the process did not resume. Thus, I gave up. OK, so stuck forever ;). Interesting. So we probably missed a wakeup somehow or j_barrier_count got corrupted. I suppose you are not able to reproduce the hang, are you? Looking at the code, it looks safe and I have no clue how it could happen. So unless you are able to see the issue again (so that we can gather some more debug information), I'm not able to help... I'm sorry. Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-02-17 15:38 ` Jan Kara @ 2011-04-08 14:38 ` Tetsuo Handa 2011-04-08 18:29 ` Jan Kara 0 siblings, 1 reply; 11+ messages in thread From: Tetsuo Handa @ 2011-04-08 14:38 UTC (permalink / raw) To: jack; +Cc: linux-fsdevel Jan Kara wrote: > > I waited for a few hours but the process did not resume. Thus, I gave up. > OK, so stuck forever ;). Interesting. So we probably missed a wakeup > somehow or j_barrier_count got corrupted. I suppose you are not able to > reproduce the hang, are you? Looking at the code, it looks safe and I have > no clue how it could happen. So unless you are able to see the issue again > (so that we can gather some more debug information), I'm not able to help... I don't know how to reproduce the hang, but I got below message (I think it was 2.6.18-238.5.1.el5) and CPU usage became 100% soon after I resumed a VM (which took a few *minutes* to resume) running on the VMware Workstation. INFO: task kjournald:543 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. kjournald D 00000122 3072 543 9 573 530 (L-TLB) c193cf40 00000046 c37e5098 00000122 c1a41254 00000001 c193cf18 00000001 f7c25aa0 c3807a0a 00000122 00022972 00000000 f7c25bac c1806f00 f7096e40 f7c25aa0 00000000 c195ec50 c1803e00 f7096e40 c195eaa0 c193cf70 ffffffff Call Trace: [<f886609b>] journal_commit_transaction+0x137/0xefc [jbd] [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<c042df7e>] try_to_del_timer_sync+0x65/0x6c [<f8869c21>] kjournald+0xa1/0x1c2 [jbd] [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<f8869b80>] kjournald+0x0/0x1c2 [jbd] [<c0436af7>] kthread+0xc0/0xed [<c0436a37>] kthread+0x0/0xed [<c0405c87>] kernel_thread_helper+0x7/0x10 ======================= INFO: task login:2107 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. login D 00000151 2752 2107 1 2108 604 (NOTLB) c1940f38 00000086 ff6037b8 00000151 00000000 c1940f3c c0484602 0000000a f7c25000 ffd43070 00000151 0073f8b8 00000000 f7c2510c c1806f00 f49683c0 f1eff380 00000000 c0475922 f7d6d8c0 f7679cc8 f1eff380 c1940f3c ffffffff Call Trace: [<c0484602>] may_open+0x125/0x203 [<c0475922>] __dentry_open+0xea/0x1ab [<c06201a5>] __mutex_lock_slowpath+0x4d/0x7c [<c06201e3>] .text.lock.mutex+0xf/0x14 [<c049b1f3>] inotify_inode_queue_event+0x45/0xc6 [<c0477828>] generic_file_llseek+0x2a/0xd2 [<c04777fe>] generic_file_llseek+0x0/0xd2 [<c0476b41>] vfs_llseek+0x30/0x34 [<c0477a31>] sys_llseek+0x43/0x84 [<c04873a0>] sys_fcntl64+0x6f/0x80 [<c0404f4b>] syscall_call+0x7/0xb ======================= INFO: task syslogd:2633 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. syslogd D 00000122 2412 2633 1 2636 2621 (NOTLB) f7138ed4 00000082 c35f4a61 00000122 0000000e 00000000 f7138f18 00000007 c195eaa0 c37e5098 00000122 001f0637 00000000 c195ebac c1806f00 f7096e40 c04975ff 00000000 00000282 c042deff c081ef80 f7138edc c18073bc c042e073 Call Trace: [<c04975ff>] mpage_writepages+0x2b1/0x310 [<c042deff>] lock_timer_base+0x15/0x2f [<c042e073>] __mod_timer+0xda/0xe4 [<c061fe71>] schedule_timeout+0x71/0x8c [<c042d6ab>] process_timeout+0x0/0x5 [<f886459f>] journal_stop+0xd3/0x1ba [jbd] [<c0495c42>] __writeback_single_inode+0x197/0x2a3 [<c045edfc>] do_writepages+0x2b/0x32 [<c045a950>] __filemap_fdatawrite_range+0x66/0x72 [<c04962de>] sync_inode+0x19/0x24 [<f88e8009>] ext3_sync_file+0xb1/0xdc [ext3] [<c0479529>] do_fsync+0x41/0x83 [<c0479588>] __do_fsync+0x1d/0x2b [<c0404f4b>] syscall_call+0x7/0xb ======================= INFO: task auditd:2688 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. auditd D 00000122 2396 2688 1 2940 2687 (NOTLB) f4cc1ed0 00000086 c34cb5c9 00000122 c0459b22 0000000e 00000000 00000009 f77bcaa0 c35f4a61 00000122 00129498 00000000 f77bcbac c1806f00 f7096200 c1a41268 00000000 00000000 f4cc1ecc c041ec40 00000000 f4cc1ed8 c1a41250 Call Trace: [<c0459b22>] find_get_pages_tag+0x30/0x75 [<c041ec40>] __wake_up+0x2a/0x3d [<c0436d07>] prepare_to_wait+0x24/0x46 [<f88691ea>] log_wait_commit+0x80/0xc7 [jbd] [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<f8864661>] journal_stop+0x195/0x1ba [jbd] [<c0495c42>] __writeback_single_inode+0x197/0x2a3 [<c045edfc>] do_writepages+0x2b/0x32 [<c045a950>] __filemap_fdatawrite_range+0x66/0x72 [<c04962de>] sync_inode+0x19/0x24 [<f88e8009>] ext3_sync_file+0xb1/0xdc [ext3] [<c0479529>] do_fsync+0x41/0x83 [<c0479588>] __do_fsync+0x1d/0x2b [<c0404f4b>] syscall_call+0x7/0xb ======================= INFO: task nmbd:3186 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. nmbd D 00000177 2572 3186 1 3198 3183 (NOTLB) f48c8e28 00200086 eb451402 00000177 00000010 c0637d00 00000000 00000007 f7140000 eb4f644b 00000177 000a5049 00000000 f714010c c1806f00 f77233c0 ffffffff 00000000 00000000 00000000 00000000 00000000 f48c8e40 ffffffff Call Trace: [<f8864d35>] start_this_handle+0x21b/0x30d [jbd] [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<f8864ed3>] journal_start+0xac/0xdb [jbd] [<f88ec262>] ext3_dirty_inode+0x24/0x66 [ext3] [<c0496310>] __mark_inode_dirty+0x27/0x14f [<c048e6b1>] file_update_time+0x30/0xa1 [<c0464d5b>] do_wp_page+0x5b7/0x5f1 [<c04663e6>] __handle_mm_fault+0xa33/0xaac [<c048b509>] fcntl_setlk64+0x1f9/0x21f [<c0622048>] do_page_fault+0x23a/0x52d [<c0621e0e>] do_page_fault+0x0/0x52d [<c0405abd>] error_code+0x39/0x40 ======================= INFO: task login:3370 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. login D 00000122 2672 3370 1 3288 (NOTLB) eff1cdc4 00000086 c9528bc8 00000122 00a41000 c062c080 00000007 00000009 f776f000 c9702c11 00000122 001da049 00000000 f776f10c c1806f00 f4a85900 00000000 00000000 00160057 ffffffff 00000000 ffffffff eff1cddc ffffffff Call Trace: [<f8864d35>] start_this_handle+0x21b/0x30d [jbd] [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<f8864ed3>] journal_start+0xac/0xdb [jbd] [<f88ec262>] ext3_dirty_inode+0x24/0x66 [ext3] [<c0496310>] __mark_inode_dirty+0x27/0x14f [<c048e6b1>] file_update_time+0x30/0xa1 [<c045b8dd>] __generic_file_aio_write_nolock+0x38d/0x52a [<c04c955b>] avc_has_perm+0x3c/0x46 [<c045bad1>] generic_file_aio_write+0x57/0xaa [<f88e7e91>] ext3_file_write+0x19/0x83 [ext3] [<c0476c5e>] do_sync_write+0xb6/0xf1 [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<c0476ba8>] do_sync_write+0x0/0xf1 [<c04774e7>] vfs_write+0xa1/0x143 [<c0477b11>] sys_write+0x3c/0x63 [<c0404f4b>] syscall_call+0x7/0xb ======================= INFO: task kjournald:543 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. kjournald D 00000122 3072 543 9 573 530 (L-TLB) c193cf40 00000046 c37e5098 00000122 c1a41254 00000001 c193cf18 00000001 f7c25aa0 c3807a0a 00000122 00022972 00000000 f7c25bac c1806f00 f7096e40 f7c25aa0 00000000 c195ec50 c1803e00 f7096e40 c195eaa0 c193cf70 ffffffff Call Trace: [<f886609b>] journal_commit_transaction+0x137/0xefc [jbd] [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<c042df7e>] try_to_del_timer_sync+0x65/0x6c [<f8869c21>] kjournald+0xa1/0x1c2 [jbd] [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<f8869b80>] kjournald+0x0/0x1c2 [jbd] [<c0436af7>] kthread+0xc0/0xed [<c0436a37>] kthread+0x0/0xed [<c0405c87>] kernel_thread_helper+0x7/0x10 ======================= INFO: task login:2107 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. login D 00000151 2752 2107 1 2108 604 (NOTLB) c1940f38 00000086 ff6037b8 00000151 00000000 c1940f3c c0484602 0000000a f7c25000 ffd43070 00000151 0073f8b8 00000000 f7c2510c c1806f00 f49683c0 f1eff380 00000000 c0475922 f7d6d8c0 f7679cc8 f1eff380 c1940f3c ffffffff Call Trace: [<c0484602>] may_open+0x125/0x203 [<c0475922>] __dentry_open+0xea/0x1ab [<c06201a5>] __mutex_lock_slowpath+0x4d/0x7c [<c06201e3>] .text.lock.mutex+0xf/0x14 [<c049b1f3>] inotify_inode_queue_event+0x45/0xc6 [<c0477828>] generic_file_llseek+0x2a/0xd2 [<c04777fe>] generic_file_llseek+0x0/0xd2 [<c0476b41>] vfs_llseek+0x30/0x34 [<c0477a31>] sys_llseek+0x43/0x84 [<c04873a0>] sys_fcntl64+0x6f/0x80 [<c0404f4b>] syscall_call+0x7/0xb ======================= INFO: task syslogd:2633 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. syslogd D 00000122 2412 2633 1 2636 2621 (NOTLB) f7138ed4 00000082 c35f4a61 00000122 0000000e 00000000 f7138f18 00000007 c195eaa0 c37e5098 00000122 001f0637 00000000 c195ebac c1806f00 f7096e40 c04975ff 00000000 00000282 c042deff c081ef80 f7138edc c18073bc c042e073 Call Trace: [<c04975ff>] mpage_writepages+0x2b1/0x310 [<c042deff>] lock_timer_base+0x15/0x2f [<c042e073>] __mod_timer+0xda/0xe4 [<c061fe71>] schedule_timeout+0x71/0x8c [<c042d6ab>] process_timeout+0x0/0x5 [<f886459f>] journal_stop+0xd3/0x1ba [jbd] [<c0495c42>] __writeback_single_inode+0x197/0x2a3 [<c045edfc>] do_writepages+0x2b/0x32 [<c045a950>] __filemap_fdatawrite_range+0x66/0x72 [<c04962de>] sync_inode+0x19/0x24 [<f88e8009>] ext3_sync_file+0xb1/0xdc [ext3] [<c0479529>] do_fsync+0x41/0x83 [<c0479588>] __do_fsync+0x1d/0x2b [<c0404f4b>] syscall_call+0x7/0xb ======================= INFO: task auditd:2688 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. auditd D 00000122 2396 2688 1 2940 2687 (NOTLB) f4cc1ed0 00000086 c34cb5c9 00000122 c0459b22 0000000e 00000000 00000009 f77bcaa0 c35f4a61 00000122 00129498 00000000 f77bcbac c1806f00 f7096200 c1a41268 00000000 00000000 f4cc1ecc c041ec40 00000000 f4cc1ed8 c1a41250 Call Trace: [<c0459b22>] find_get_pages_tag+0x30/0x75 [<c041ec40>] __wake_up+0x2a/0x3d [<c0436d07>] prepare_to_wait+0x24/0x46 [<f88691ea>] log_wait_commit+0x80/0xc7 [jbd] [<c0436bbb>] autoremove_wake_function+0x0/0x2d [<f8864661>] journal_stop+0x195/0x1ba [jbd] [<c0495c42>] __writeback_single_inode+0x197/0x2a3 [<c045edfc>] do_writepages+0x2b/0x32 [<c045a950>] __filemap_fdatawrite_range+0x66/0x72 [<c04962de>] sync_inode+0x19/0x24 [<f88e8009>] ext3_sync_file+0xb1/0xdc [ext3] [<c0479529>] do_fsync+0x41/0x83 [<c0479588>] __do_fsync+0x1d/0x2b [<c0404f4b>] syscall_call+0x7/0xb ======================= If this comes from the same cause, it might be related with clock or timer event. I couldn't get more information because sysrq didn't work. ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-04-08 14:38 ` Tetsuo Handa @ 2011-04-08 18:29 ` Jan Kara 2011-04-09 2:21 ` Tetsuo Handa 0 siblings, 1 reply; 11+ messages in thread From: Jan Kara @ 2011-04-08 18:29 UTC (permalink / raw) To: Tetsuo Handa; +Cc: jack, linux-fsdevel On Fri 08-04-11 23:38:55, Tetsuo Handa wrote: > Jan Kara wrote: > > > I waited for a few hours but the process did not resume. Thus, I gave up. > > OK, so stuck forever ;). Interesting. So we probably missed a wakeup > > somehow or j_barrier_count got corrupted. I suppose you are not able to > > reproduce the hang, are you? Looking at the code, it looks safe and I have > > no clue how it could happen. So unless you are able to see the issue again > > (so that we can gather some more debug information), I'm not able to help... > > I don't know how to reproduce the hang, but I got below message (I think it was > 2.6.18-238.5.1.el5) and CPU usage became 100% soon after I resumed a VM (which > took a few *minutes* to resume) running on the VMware Workstation. Hmm, but 2.6.18 is really ancient. I'm afraid I cannot help you much with it. There have been numerous bugs fixed since then. > INFO: task kjournald:543 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > kjournald D 00000122 3072 543 9 573 530 (L-TLB) > c193cf40 00000046 c37e5098 00000122 c1a41254 00000001 c193cf18 00000001 > f7c25aa0 c3807a0a 00000122 00022972 00000000 f7c25bac c1806f00 f7096e40 > f7c25aa0 00000000 c195ec50 c1803e00 f7096e40 c195eaa0 c193cf70 ffffffff > Call Trace: > [<f886609b>] journal_commit_transaction+0x137/0xefc [jbd] > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<c042df7e>] try_to_del_timer_sync+0x65/0x6c > [<f8869c21>] kjournald+0xa1/0x1c2 [jbd] > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<f8869b80>] kjournald+0x0/0x1c2 [jbd] > [<c0436af7>] kthread+0xc0/0xed > [<c0436a37>] kthread+0x0/0xed > [<c0405c87>] kernel_thread_helper+0x7/0x10 > ======================= > INFO: task login:2107 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > login D 00000151 2752 2107 1 2108 604 (NOTLB) > c1940f38 00000086 ff6037b8 00000151 00000000 c1940f3c c0484602 0000000a > f7c25000 ffd43070 00000151 0073f8b8 00000000 f7c2510c c1806f00 f49683c0 > f1eff380 00000000 c0475922 f7d6d8c0 f7679cc8 f1eff380 c1940f3c ffffffff > Call Trace: > [<c0484602>] may_open+0x125/0x203 > [<c0475922>] __dentry_open+0xea/0x1ab > [<c06201a5>] __mutex_lock_slowpath+0x4d/0x7c > [<c06201e3>] .text.lock.mutex+0xf/0x14 > [<c049b1f3>] inotify_inode_queue_event+0x45/0xc6 > [<c0477828>] generic_file_llseek+0x2a/0xd2 > [<c04777fe>] generic_file_llseek+0x0/0xd2 > [<c0476b41>] vfs_llseek+0x30/0x34 > [<c0477a31>] sys_llseek+0x43/0x84 > [<c04873a0>] sys_fcntl64+0x6f/0x80 > [<c0404f4b>] syscall_call+0x7/0xb > ======================= > INFO: task syslogd:2633 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > syslogd D 00000122 2412 2633 1 2636 2621 (NOTLB) > f7138ed4 00000082 c35f4a61 00000122 0000000e 00000000 f7138f18 00000007 > c195eaa0 c37e5098 00000122 001f0637 00000000 c195ebac c1806f00 f7096e40 > c04975ff 00000000 00000282 c042deff c081ef80 f7138edc c18073bc c042e073 > Call Trace: > [<c04975ff>] mpage_writepages+0x2b1/0x310 > [<c042deff>] lock_timer_base+0x15/0x2f > [<c042e073>] __mod_timer+0xda/0xe4 > [<c061fe71>] schedule_timeout+0x71/0x8c > [<c042d6ab>] process_timeout+0x0/0x5 > [<f886459f>] journal_stop+0xd3/0x1ba [jbd] > [<c0495c42>] __writeback_single_inode+0x197/0x2a3 > [<c045edfc>] do_writepages+0x2b/0x32 > [<c045a950>] __filemap_fdatawrite_range+0x66/0x72 > [<c04962de>] sync_inode+0x19/0x24 > [<f88e8009>] ext3_sync_file+0xb1/0xdc [ext3] > [<c0479529>] do_fsync+0x41/0x83 > [<c0479588>] __do_fsync+0x1d/0x2b > [<c0404f4b>] syscall_call+0x7/0xb > ======================= > INFO: task auditd:2688 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > auditd D 00000122 2396 2688 1 2940 2687 (NOTLB) > f4cc1ed0 00000086 c34cb5c9 00000122 c0459b22 0000000e 00000000 00000009 > f77bcaa0 c35f4a61 00000122 00129498 00000000 f77bcbac c1806f00 f7096200 > c1a41268 00000000 00000000 f4cc1ecc c041ec40 00000000 f4cc1ed8 c1a41250 > Call Trace: > [<c0459b22>] find_get_pages_tag+0x30/0x75 > [<c041ec40>] __wake_up+0x2a/0x3d > [<c0436d07>] prepare_to_wait+0x24/0x46 > [<f88691ea>] log_wait_commit+0x80/0xc7 [jbd] > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<f8864661>] journal_stop+0x195/0x1ba [jbd] > [<c0495c42>] __writeback_single_inode+0x197/0x2a3 > [<c045edfc>] do_writepages+0x2b/0x32 > [<c045a950>] __filemap_fdatawrite_range+0x66/0x72 > [<c04962de>] sync_inode+0x19/0x24 > [<f88e8009>] ext3_sync_file+0xb1/0xdc [ext3] > [<c0479529>] do_fsync+0x41/0x83 > [<c0479588>] __do_fsync+0x1d/0x2b > [<c0404f4b>] syscall_call+0x7/0xb > ======================= > INFO: task nmbd:3186 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > nmbd D 00000177 2572 3186 1 3198 3183 (NOTLB) > f48c8e28 00200086 eb451402 00000177 00000010 c0637d00 00000000 00000007 > f7140000 eb4f644b 00000177 000a5049 00000000 f714010c c1806f00 f77233c0 > ffffffff 00000000 00000000 00000000 00000000 00000000 f48c8e40 ffffffff > Call Trace: > [<f8864d35>] start_this_handle+0x21b/0x30d [jbd] > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<f8864ed3>] journal_start+0xac/0xdb [jbd] > [<f88ec262>] ext3_dirty_inode+0x24/0x66 [ext3] > [<c0496310>] __mark_inode_dirty+0x27/0x14f > [<c048e6b1>] file_update_time+0x30/0xa1 > [<c0464d5b>] do_wp_page+0x5b7/0x5f1 > [<c04663e6>] __handle_mm_fault+0xa33/0xaac > [<c048b509>] fcntl_setlk64+0x1f9/0x21f > [<c0622048>] do_page_fault+0x23a/0x52d > [<c0621e0e>] do_page_fault+0x0/0x52d > [<c0405abd>] error_code+0x39/0x40 > ======================= > INFO: task login:3370 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > login D 00000122 2672 3370 1 3288 (NOTLB) > eff1cdc4 00000086 c9528bc8 00000122 00a41000 c062c080 00000007 00000009 > f776f000 c9702c11 00000122 001da049 00000000 f776f10c c1806f00 f4a85900 > 00000000 00000000 00160057 ffffffff 00000000 ffffffff eff1cddc ffffffff > Call Trace: > [<f8864d35>] start_this_handle+0x21b/0x30d [jbd] > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<f8864ed3>] journal_start+0xac/0xdb [jbd] > [<f88ec262>] ext3_dirty_inode+0x24/0x66 [ext3] > [<c0496310>] __mark_inode_dirty+0x27/0x14f > [<c048e6b1>] file_update_time+0x30/0xa1 > [<c045b8dd>] __generic_file_aio_write_nolock+0x38d/0x52a > [<c04c955b>] avc_has_perm+0x3c/0x46 > [<c045bad1>] generic_file_aio_write+0x57/0xaa > [<f88e7e91>] ext3_file_write+0x19/0x83 [ext3] > [<c0476c5e>] do_sync_write+0xb6/0xf1 > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<c0476ba8>] do_sync_write+0x0/0xf1 > [<c04774e7>] vfs_write+0xa1/0x143 > [<c0477b11>] sys_write+0x3c/0x63 > [<c0404f4b>] syscall_call+0x7/0xb > ======================= > INFO: task kjournald:543 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > kjournald D 00000122 3072 543 9 573 530 (L-TLB) > c193cf40 00000046 c37e5098 00000122 c1a41254 00000001 c193cf18 00000001 > f7c25aa0 c3807a0a 00000122 00022972 00000000 f7c25bac c1806f00 f7096e40 > f7c25aa0 00000000 c195ec50 c1803e00 f7096e40 c195eaa0 c193cf70 ffffffff > Call Trace: > [<f886609b>] journal_commit_transaction+0x137/0xefc [jbd] > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<c042df7e>] try_to_del_timer_sync+0x65/0x6c > [<f8869c21>] kjournald+0xa1/0x1c2 [jbd] > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<f8869b80>] kjournald+0x0/0x1c2 [jbd] > [<c0436af7>] kthread+0xc0/0xed > [<c0436a37>] kthread+0x0/0xed > [<c0405c87>] kernel_thread_helper+0x7/0x10 > ======================= > INFO: task login:2107 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > login D 00000151 2752 2107 1 2108 604 (NOTLB) > c1940f38 00000086 ff6037b8 00000151 00000000 c1940f3c c0484602 0000000a > f7c25000 ffd43070 00000151 0073f8b8 00000000 f7c2510c c1806f00 f49683c0 > f1eff380 00000000 c0475922 f7d6d8c0 f7679cc8 f1eff380 c1940f3c ffffffff > Call Trace: > [<c0484602>] may_open+0x125/0x203 > [<c0475922>] __dentry_open+0xea/0x1ab > [<c06201a5>] __mutex_lock_slowpath+0x4d/0x7c > [<c06201e3>] .text.lock.mutex+0xf/0x14 > [<c049b1f3>] inotify_inode_queue_event+0x45/0xc6 > [<c0477828>] generic_file_llseek+0x2a/0xd2 > [<c04777fe>] generic_file_llseek+0x0/0xd2 > [<c0476b41>] vfs_llseek+0x30/0x34 > [<c0477a31>] sys_llseek+0x43/0x84 > [<c04873a0>] sys_fcntl64+0x6f/0x80 > [<c0404f4b>] syscall_call+0x7/0xb > ======================= > INFO: task syslogd:2633 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > syslogd D 00000122 2412 2633 1 2636 2621 (NOTLB) > f7138ed4 00000082 c35f4a61 00000122 0000000e 00000000 f7138f18 00000007 > c195eaa0 c37e5098 00000122 001f0637 00000000 c195ebac c1806f00 f7096e40 > c04975ff 00000000 00000282 c042deff c081ef80 f7138edc c18073bc c042e073 > Call Trace: > [<c04975ff>] mpage_writepages+0x2b1/0x310 > [<c042deff>] lock_timer_base+0x15/0x2f > [<c042e073>] __mod_timer+0xda/0xe4 > [<c061fe71>] schedule_timeout+0x71/0x8c > [<c042d6ab>] process_timeout+0x0/0x5 > [<f886459f>] journal_stop+0xd3/0x1ba [jbd] > [<c0495c42>] __writeback_single_inode+0x197/0x2a3 > [<c045edfc>] do_writepages+0x2b/0x32 > [<c045a950>] __filemap_fdatawrite_range+0x66/0x72 > [<c04962de>] sync_inode+0x19/0x24 > [<f88e8009>] ext3_sync_file+0xb1/0xdc [ext3] > [<c0479529>] do_fsync+0x41/0x83 > [<c0479588>] __do_fsync+0x1d/0x2b > [<c0404f4b>] syscall_call+0x7/0xb > ======================= > INFO: task auditd:2688 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > auditd D 00000122 2396 2688 1 2940 2687 (NOTLB) > f4cc1ed0 00000086 c34cb5c9 00000122 c0459b22 0000000e 00000000 00000009 > f77bcaa0 c35f4a61 00000122 00129498 00000000 f77bcbac c1806f00 f7096200 > c1a41268 00000000 00000000 f4cc1ecc c041ec40 00000000 f4cc1ed8 c1a41250 > Call Trace: > [<c0459b22>] find_get_pages_tag+0x30/0x75 > [<c041ec40>] __wake_up+0x2a/0x3d > [<c0436d07>] prepare_to_wait+0x24/0x46 > [<f88691ea>] log_wait_commit+0x80/0xc7 [jbd] > [<c0436bbb>] autoremove_wake_function+0x0/0x2d > [<f8864661>] journal_stop+0x195/0x1ba [jbd] > [<c0495c42>] __writeback_single_inode+0x197/0x2a3 > [<c045edfc>] do_writepages+0x2b/0x32 > [<c045a950>] __filemap_fdatawrite_range+0x66/0x72 > [<c04962de>] sync_inode+0x19/0x24 > [<f88e8009>] ext3_sync_file+0xb1/0xdc [ext3] > [<c0479529>] do_fsync+0x41/0x83 > [<c0479588>] __do_fsync+0x1d/0x2b > [<c0404f4b>] syscall_call+0x7/0xb > ======================= > > If this comes from the same cause, it might be related with clock or timer event. > I couldn't get more information because sysrq didn't work. I see. From the traces it looks as if some processes are waiting in journal_stop() in transaction batching code (which then blocks a transaction commit). So indeed if the timer / wakeup code didn't work quite well, it could cause situations like this. Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-04-08 18:29 ` Jan Kara @ 2011-04-09 2:21 ` Tetsuo Handa 2011-04-12 19:50 ` Jan Kara 0 siblings, 1 reply; 11+ messages in thread From: Tetsuo Handa @ 2011-04-09 2:21 UTC (permalink / raw) To: jack; +Cc: linux-fsdevel Jan Kara wrote: > Hmm, but 2.6.18 is really ancient. I'm afraid I cannot help you much with > it. There have been numerous bugs fixed since then. It is RHEL5.6 kernel which the known bugs have been fixed. I guess that RHEL6.0 kernel also has this bug (since this bug is in Ubuntu 10.04 kernels). So, I want to try establishing the steps to reproduce. Does anybody come up with common characteristics between below hangups? (a) Updating rpm packages using rpm executed from zypper. Although, the process actually hanged is /bin/sh which I guess was invoked for pre- or post- install scripts. Installing: grub-0.97-173.6 [91%] (b) Logging in from console using /bin/login . Although, the process actually hanged seems to be auditd process which attempted to write an audit log immediately after login event. (c) PostgreSQL and Apache. http://www.mail-archive.com/pgsql-bugs@postgresql.org/msg24852.html Writing with O_SYNC? Or calling fsync()? Or calling ftruncate()? Or ...? ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-04-09 2:21 ` Tetsuo Handa @ 2011-04-12 19:50 ` Jan Kara 2011-04-12 22:00 ` Tetsuo Handa 0 siblings, 1 reply; 11+ messages in thread From: Jan Kara @ 2011-04-12 19:50 UTC (permalink / raw) To: Tetsuo Handa; +Cc: jack, linux-fsdevel On Sat 09-04-11 11:21:40, Tetsuo Handa wrote: > Jan Kara wrote: > > Hmm, but 2.6.18 is really ancient. I'm afraid I cannot help you much with > > it. There have been numerous bugs fixed since then. > > It is RHEL5.6 kernel which the known bugs have been fixed. I guess that RHEL6.0 Yes, but RHEL (as well as SLES) kernels are generally fixed on as needed basis - i.e., when a customer reports an error, support debugs it and adds the fix to the kernel. So you could well be the first one to spot the issue with RHEL 5.6 kernel... > kernel also has this bug (since this bug is in Ubuntu 10.04 kernels). Yes, Ubuntu 10.04 is more relevant. 2.6.32 is not that old and I don't remember any fixes in that area. > So, I want to try establishing the steps to reproduce. > > Does anybody come up with common characteristics between below hangups? > > (a) Updating rpm packages using rpm executed from zypper. > > Although, the process actually hanged is /bin/sh which > I guess was invoked for pre- or post- install scripts. > > Installing: grub-0.97-173.6 [91%] > > (b) Logging in from console using /bin/login . > > Although, the process actually hanged seems to be auditd process > which attempted to write an audit log immediately after login event. > > (c) PostgreSQL and Apache. > > http://www.mail-archive.com/pgsql-bugs@postgresql.org/msg24852.html > > Writing with O_SYNC? Or calling fsync()? Or calling ftruncate()? Or ...? I wouldn't expect any of this. If your original Ubuntu 10.04 report is right, we block on j_barrier_count which is changed only in journal_lock/unlock_updates() which gets called only from a few places. The problem is that the hung process need not be directly related to the hang. It can be just a victim of a race with some other process manipulating j_barrier_count. But I don't see any such race in the code. So I'd need a way to reproduce this so that we can perform some debugging. Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-04-12 19:50 ` Jan Kara @ 2011-04-12 22:00 ` Tetsuo Handa 0 siblings, 0 replies; 11+ messages in thread From: Tetsuo Handa @ 2011-04-12 22:00 UTC (permalink / raw) To: jack; +Cc: linux-fsdevel Jan Kara wrote: > The problem is that the hung process need not be directly related to the > hang. It can be just a victim of a race with some other process > manipulating j_barrier_count. I agree. /bin/sh would not hang by such simple write() call. /bin/sh will be a victim of somebody else's write() calls. But I think these three cases have something characteristic point. For updating rpm's database, I think rpm would wait for data to be written (using O_SYNC or fsync()). For auditing login event, I think the issuer of audit event would wait for data to be written. For postgresql, I think postmaster would wait for transaction log to be written. So, my guess is multiple threads are writing data (maybe one is sync mode and another is async mode, maybe one is calling fsync() and another is calling write()). I wish there are test programs that cover such combinations. If this hang occurs by simply multiple threads writing data in async mode, this hang must have been reported so many times. ^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2011-04-12 22:00 UTC | newest] Thread overview: 11+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2011-02-08 5:26 [2.6.32 ubuntu] I/O hang at start_this_handle Tetsuo Handa 2011-02-15 15:16 ` Jan Kara 2011-02-15 21:52 ` Tetsuo Handa 2011-02-16 15:53 ` Jan Kara 2011-02-17 8:13 ` Tetsuo Handa 2011-02-17 15:38 ` Jan Kara 2011-04-08 14:38 ` Tetsuo Handa 2011-04-08 18:29 ` Jan Kara 2011-04-09 2:21 ` Tetsuo Handa 2011-04-12 19:50 ` Jan Kara 2011-04-12 22:00 ` Tetsuo Handa
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).