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