* Re: [2.6.32 ubuntu] I/O hang at start_this_handle [not found] <201102080526.p185Q0mL034909@www262.sakura.ne.jp> @ 2011-02-15 15:16 ` Jan Kara 2011-02-15 21:52 ` Tetsuo Handa 0 siblings, 1 reply; 5+ 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] 5+ messages in thread
* Re: [2.6.32 ubuntu] I/O hang at start_this_handle 2011-02-15 15:16 ` [2.6.32 ubuntu] I/O hang at start_this_handle Jan Kara @ 2011-02-15 21:52 ` Tetsuo Handa 2011-02-16 15:53 ` Jan Kara 0 siblings, 1 reply; 5+ 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(). -- 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] 5+ 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; 5+ 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] 5+ 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; 5+ 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] 5+ 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 0 siblings, 0 replies; 5+ 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 -- 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] 5+ messages in thread
end of thread, other threads:[~2011-02-17 15:38 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <201102080526.p185Q0mL034909@www262.sakura.ne.jp>
2011-02-15 15:16 ` [2.6.32 ubuntu] I/O hang at start_this_handle 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
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).