Yet another ext4/jbd2 lockup

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hello, 

Again, I have come up against a rather annoying ext4/jbd2 
lock and I'm not sure it's the same issue as the last one 
I posted (http://marc.info/?l=linux-ext4&m=143522748527527&w=2). 
Again, all of this is happening on an 3.12.28 kernel. I did grep for
the ext4 commits that have come afterwards but none of them allude to
fixing something similar. This time the blocked process is an rsync 
which has been running OUTSIDE of a container e.g. in the / cgroup 
but it was copying stuff from a dm-thin volume acting as the root 
device for a cgroup: 

rsync           D ffffffff81622100     0 33158      1 0x00000004
 ffff882ad6257b18 0000000000000086 ffff883cfb3e5280 0000000000011640
 ffff882ad6257fd8 ffff882ad6256010 0000000000011640 0000000000011640
 ffff882ad6257fd8 0000000000011640 ffff881fd3213180 ffff883cfb3e5280
Call Trace:
 [<ffffffff81573f24>] schedule+0x24/0x70
 [<ffffffff8122f64c>] wait_transaction_locked+0x7c/0xb0
 [<ffffffff81097a70>] ? wake_up_bit+0x40/0x40
 [<ffffffff8122faf2>] start_this_handle+0x2c2/0x660
 [<ffffffff8116a8fd>] ? d_rehash+0x1d/0x30
 [<ffffffff8113b7f5>] ? kmem_cache_alloc+0xb5/0x150
 [<ffffffff81230229>] jbd2__journal_start+0x109/0x1b0
 [<ffffffff8120fe31>] __ext4_journal_start_sb+0x61/0xb0
 [<ffffffff811ebbe7>] __ext4_new_inode+0x5b7/0x1330
 [<ffffffff8115db8e>] ? __lookup_hash+0x1e/0x40
 [<ffffffff811fb7ec>] ext4_mkdir+0x18c/0x400
 [<ffffffff8115de05>] ? generic_permission+0xc5/0x230
 [<ffffffff8115f018>] vfs_mkdir+0xb8/0x100
 [<ffffffff811614e2>] SyS_mkdirat+0xb2/0x100
 [<ffffffff8115dc44>] SyS_mkdir+0x14/0x20
 [<ffffffff815763a2>] system_call_fastpath+0x16/0x1b

Sampling echo "w" > /proc/sysrq-trigger I found some other 
blocked process which might be related to the issue. In particular: 

jbd2/dm-24-8    D 0000000000000000     0 31263      2 0x00000000
 ffff882af46df9f8 0000000000000046 ffff882643db0000 0000000000011640
 ffff882af46dffd8 ffff882af46de010 0000000000011640 0000000000011640
 ffff882af46dffd8 0000000000011640 ffff8827c519ca40 ffff882643db0000
Call Trace:
 [<ffffffff810f4fc0>] ? __lock_page+0x70/0x70
 [<ffffffff81573f24>] schedule+0x24/0x70
 [<ffffffff81573ff7>] io_schedule+0x87/0xd0
 [<ffffffff810f4fc9>] sleep_on_page+0x9/0x10
 [<ffffffff81571a45>] __wait_on_bit_lock+0x55/0xb0
 [<ffffffff810f4b0a>] ? find_get_pages_tag+0xca/0x170
 [<ffffffff810f4fb2>] __lock_page+0x62/0x70
 [<ffffffff81097af0>] ? wake_atomic_t_function+0x40/0x40
 [<ffffffff81101c30>] ? pagevec_lookup_tag+0x20/0x30
 [<ffffffff810fffe1>] write_cache_pages+0x391/0x470
 [<ffffffff810fec20>] ? set_page_dirty+0x60/0x60
 [<ffffffff8110010c>] generic_writepages+0x4c/0x70
 [<ffffffff81231b0b>] jbd2_journal_commit_transaction+0x41b/0x1790
 [<ffffffff81083be7>] ? lock_timer_base+0x37/0x70
 [<ffffffff81235d12>] kjournald2+0xc2/0x250
 [<ffffffff81097a70>] ? wake_up_bit+0x40/0x40
 [<ffffffff81235c50>] ? commit_timeout+0x10/0x10
 [<ffffffff81097456>] kthread+0xc6/0xd0
 [<ffffffff81097390>] ? kthread_freezable_should_stop+0x60/0x60
 [<ffffffff815762fc>] ret_from_fork+0x7c/0xb0
 [<ffffffff81097390>] ? kthread_freezable_should_stop+0x60/0x60

kworker/u81:90  D 0000000000000000     0 36695      2 0x00000000
Workqueue: writeback bdi_writeback_workfn (flush-253:24)
 ffff880155ee7888 0000000000000046 ffff881ea1a71080 0000000000011640
 ffff880155ee7fd8 ffff880155ee6010 0000000000011640 0000000000011640
 ffff880155ee7fd8 0000000000011640 ffff882119215ac0 ffff881ea1a71080
Call Trace:
 [<ffffffff81573f24>] schedule+0x24/0x70
 [<ffffffff81235bc5>] jbd2_log_wait_commit+0xb5/0x130
 [<ffffffff81097a70>] ? wake_up_bit+0x40/0x40
 [<ffffffff810a04ce>] ? __wake_up+0x4e/0x70
 [<ffffffff8122f43b>] jbd2_journal_stop+0x1bb/0x2c0
 [<ffffffff8120fda8>] __ext4_journal_stop+0x78/0xa0
 [<ffffffff811f366f>] ext4_writepages+0x45f/0xa50
 [<ffffffff8110014b>] do_writepages+0x1b/0x30
 [<ffffffff811794cd>] __writeback_single_inode+0x3d/0x130
 [<ffffffff8117a637>] writeback_sb_inodes+0x207/0x3f0
 [<ffffffff8117a8b6>] __writeback_inodes_wb+0x96/0xc0
 [<ffffffff8117aabb>] wb_writeback+0x1db/0x1f0
 [<ffffffff8117ac61>] wb_do_writeback+0x191/0x1a0
 [<ffffffff8117ace8>] bdi_writeback_workfn+0x78/0x1b0
 [<ffffffff810a4312>] ? wake_up_process+0x22/0x40
 [<ffffffff8109078b>] process_one_work+0x13b/0x460
 [<ffffffff81091a09>] worker_thread+0x119/0x3f0
 [<ffffffff810918f0>] ? manage_workers+0x2c0/0x2c0
 [<ffffffff81097456>] kthread+0xc6/0xd0
 [<ffffffff81097390>] ? kthread_freezable_should_stop+0x60/0x60
 [<ffffffff815762fc>] ret_from_fork+0x7c/0xb0
 [<ffffffff81097390>] ? kthread_freezable_should_stop+0x60/0x60

Basically dm-24 is the device this rsync was syncing from  and the 
kworker is running as part of writeback for the same device 
(253:24 is the major:minor for this particular device). 
Furthermore, I see there have been a number of "sync" executed and 
their stack traces look like the following: 

sync            D ffffffff81622100     0 17596  17532 0x00000000
 ffff8827cf1fdd78 0000000000000086 ffff88348291b9c0 0000000000011640
 ffff8827cf1fdfd8 ffff8827cf1fc010 0000000000011640 0000000000011640
 ffff8827cf1fdfd8 0000000000011640 ffff881fd32118c0 ffff88348291b9c0
Call Trace:
 [<ffffffff81573f24>] schedule+0x24/0x70
 [<ffffffff81571955>] schedule_timeout+0x185/0x1c0
 [<ffffffff810904c2>] ? __queue_delayed_work+0x82/0x150
 [<ffffffff81574984>] wait_for_completion+0x94/0x100
 [<ffffffff810a42d0>] ? try_to_wake_up+0x2b0/0x2b0
 [<ffffffff81179a28>] ? bdi_queue_work+0x48/0xb0
 [<ffffffff8117e830>] ? fdatawrite_one_bdev+0x20/0x20
 [<ffffffff81179c56>] sync_inodes_sb+0xa6/0x1c0
 [<ffffffff8117e830>] ? fdatawrite_one_bdev+0x20/0x20
 [<ffffffff8117e845>] sync_inodes_one_sb+0x15/0x20
 [<ffffffff81157b29>] iterate_supers+0xa9/0xe0
 [<ffffffff8117e880>] sys_sync+0x30/0x90
 [<ffffffff815763a2>] system_call_fastpath+0x16/0x1b

I believe it is this sync which has triggered the bdi_writeback_workfn 
for the particular dm device. Essentially what I gather is that the 
rsync is locked since it wants to do some filesystem activity, hence 
it wants to start a transaction but it's blocked due to an unfinished 
transaction - presumably the one from the writeback path. However, 
the writeback is blocked in jbd2_log_wait_commit, waiting for its 
own transaction to complete and it is not progressing due to some 
reason. There hasn't been any OOM messages for the container in 
question and the global OOM killer hasn't triggered. The memory 
state of the machine when this was observed. There still some 
memory: 

SysRq : Show Memory
Mem-Info:
Node 0 DMA per-cpu:
CPU    0: hi:    0, btch:   1 usd:   0
CPU    1: hi:    0, btch:   1 usd:   0
CPU    2: hi:    0, btch:   1 usd:   0
CPU    3: hi:    0, btch:   1 usd:   0
CPU    4: hi:    0, btch:   1 usd:   0
CPU    5: hi:    0, btch:   1 usd:   0
CPU    6: hi:    0, btch:   1 usd:   0
CPU    7: hi:    0, btch:   1 usd:   0
CPU    8: hi:    0, btch:   1 usd:   0
CPU    9: hi:    0, btch:   1 usd:   0
CPU   10: hi:    0, btch:   1 usd:   0
CPU   11: hi:    0, btch:   1 usd:   0
CPU   12: hi:    0, btch:   1 usd:   0
CPU   13: hi:    0, btch:   1 usd:   0
CPU   14: hi:    0, btch:   1 usd:   0
CPU   15: hi:    0, btch:   1 usd:   0
CPU   16: hi:    0, btch:   1 usd:   0
CPU   17: hi:    0, btch:   1 usd:   0
CPU   18: hi:    0, btch:   1 usd:   0
CPU   19: hi:    0, btch:   1 usd:   0
CPU   20: hi:    0, btch:   1 usd:   0
CPU   21: hi:    0, btch:   1 usd:   0
CPU   22: hi:    0, btch:   1 usd:   0
CPU   23: hi:    0, btch:   1 usd:   0
CPU   24: hi:    0, btch:   1 usd:   0
CPU   25: hi:    0, btch:   1 usd:   0
CPU   26: hi:    0, btch:   1 usd:   0
CPU   27: hi:    0, btch:   1 usd:   0
CPU   28: hi:    0, btch:   1 usd:   0
CPU   29: hi:    0, btch:   1 usd:   0
CPU   30: hi:    0, btch:   1 usd:   0
CPU   31: hi:    0, btch:   1 usd:   0
CPU   32: hi:    0, btch:   1 usd:   0
CPU   33: hi:    0, btch:   1 usd:   0
CPU   34: hi:    0, btch:   1 usd:   0
CPU   35: hi:    0, btch:   1 usd:   0
CPU   36: hi:    0, btch:   1 usd:   0
CPU   37: hi:    0, btch:   1 usd:   0
CPU   38: hi:    0, btch:   1 usd:   0
CPU   39: hi:    0, btch:   1 usd:   0
Node 0 DMA32 per-cpu:
CPU    0: hi:  186, btch:  31 usd: 177
CPU    1: hi:  186, btch:  31 usd: 129
CPU    2: hi:  186, btch:  31 usd: 145
CPU    3: hi:  186, btch:  31 usd:  60
CPU    4: hi:  186, btch:  31 usd: 105
CPU    5: hi:  186, btch:  31 usd:  96
CPU    6: hi:  186, btch:  31 usd:  71
CPU    7: hi:  186, btch:  31 usd:  53
CPU    8: hi:  186, btch:  31 usd: 121
CPU    9: hi:  186, btch:  31 usd: 171
CPU   10: hi:  186, btch:  31 usd:  77
CPU   11: hi:  186, btch:  31 usd:   0
CPU   12: hi:  186, btch:  31 usd:   0
CPU   13: hi:  186, btch:  31 usd:   0
CPU   14: hi:  186, btch:  31 usd:  29
CPU   15: hi:  186, btch:  31 usd:  36
CPU   16: hi:  186, btch:  31 usd:   0
CPU   17: hi:  186, btch:  31 usd:   0
CPU   18: hi:  186, btch:  31 usd:   0
CPU   19: hi:  186, btch:  31 usd:  22
CPU   20: hi:  186, btch:  31 usd:  76
CPU   21: hi:  186, btch:  31 usd: 161
CPU   22: hi:  186, btch:  31 usd:  73
CPU   23: hi:  186, btch:  31 usd:  78
CPU   24: hi:  186, btch:  31 usd: 125
CPU   25: hi:  186, btch:  31 usd:  73
CPU   26: hi:  186, btch:  31 usd:  72
CPU   27: hi:  186, btch:  31 usd:  38
CPU   28: hi:  186, btch:  31 usd: 118
CPU   29: hi:  186, btch:  31 usd:  63
CPU   30: hi:  186, btch:  31 usd:   0
CPU   31: hi:  186, btch:  31 usd:   0
CPU   32: hi:  186, btch:  31 usd:   0
CPU   33: hi:  186, btch:  31 usd:   0
CPU   34: hi:  186, btch:  31 usd:   0
CPU   35: hi:  186, btch:  31 usd:   0
CPU   36: hi:  186, btch:  31 usd:   0
CPU   37: hi:  186, btch:  31 usd:   0
CPU   38: hi:  186, btch:  31 usd:   0
CPU   39: hi:  186, btch:  31 usd:   0
Node 0 Normal per-cpu:
CPU    0: hi:  186, btch:  31 usd: 188
CPU    1: hi:  186, btch:  31 usd: 174
CPU    2: hi:  186, btch:  31 usd: 116
CPU    3: hi:  186, btch:  31 usd:  96
CPU    4: hi:  186, btch:  31 usd: 169
CPU    5: hi:  186, btch:  31 usd: 137
CPU    6: hi:  186, btch:  31 usd: 102
CPU    7: hi:  186, btch:  31 usd:  96
CPU    8: hi:  186, btch:  31 usd: 149
CPU    9: hi:  186, btch:  31 usd: 203
CPU   10: hi:  186, btch:  31 usd: 179
CPU   11: hi:  186, btch:  31 usd: 181
CPU   12: hi:  186, btch:  31 usd: 159
CPU   13: hi:  186, btch:  31 usd: 160
CPU   14: hi:  186, btch:  31 usd: 179
CPU   15: hi:  186, btch:  31 usd: 158
CPU   16: hi:  186, btch:  31 usd: 180
CPU   17: hi:  186, btch:  31 usd: 155
CPU   18: hi:  186, btch:  31 usd: 156
CPU   19: hi:  186, btch:  31 usd: 173
CPU   20: hi:  186, btch:  31 usd: 161
CPU   21: hi:  186, btch:  31 usd: 163
CPU   22: hi:  186, btch:  31 usd: 123
CPU   23: hi:  186, btch:  31 usd: 157
CPU   24: hi:  186, btch:  31 usd:  19
CPU   25: hi:  186, btch:  31 usd: 159
CPU   26: hi:  186, btch:  31 usd: 176
CPU   27: hi:  186, btch:  31 usd: 140
CPU   28: hi:  186, btch:  31 usd: 180
CPU   29: hi:  186, btch:  31 usd: 169
CPU   30: hi:  186, btch:  31 usd: 158
CPU   31: hi:  186, btch:  31 usd: 181
CPU   32: hi:  186, btch:  31 usd: 181
CPU   33: hi:  186, btch:  31 usd: 159
CPU   34: hi:  186, btch:  31 usd: 168
CPU   35: hi:  186, btch:  31 usd: 173
CPU   36: hi:  186, btch:  31 usd: 161
CPU   37: hi:  186, btch:  31 usd: 179
CPU   38: hi:  186, btch:  31 usd: 184
CPU   39: hi:  186, btch:  31 usd: 182
Node 1 Normal per-cpu:
CPU    0: hi:  186, btch:  31 usd: 164
CPU    1: hi:  186, btch:  31 usd: 167
CPU    2: hi:  186, btch:  31 usd: 160
CPU    3: hi:  186, btch:  31 usd: 171
CPU    4: hi:  186, btch:  31 usd: 175
CPU    5: hi:  186, btch:  31 usd: 184
CPU    6: hi:  186, btch:  31 usd: 169
CPU    7: hi:  186, btch:  31 usd: 159
CPU    8: hi:  186, btch:  31 usd: 171
CPU    9: hi:  186, btch:  31 usd: 185
CPU   10: hi:  186, btch:  31 usd:  86
CPU   11: hi:  186, btch:  31 usd:  73
CPU   12: hi:  186, btch:  31 usd:  29
CPU   13: hi:  186, btch:  31 usd:  62
CPU   14: hi:  186, btch:  31 usd:  91
CPU   15: hi:  186, btch:  31 usd: 114
CPU   16: hi:  186, btch:  31 usd:  69
CPU   17: hi:  186, btch:  31 usd: 117
CPU   18: hi:  186, btch:  31 usd:  17
CPU   19: hi:  186, btch:  31 usd:  20
CPU   20: hi:  186, btch:  31 usd: 163
CPU   21: hi:  186, btch:  31 usd: 161
CPU   22: hi:  186, btch:  31 usd: 175
CPU   23: hi:  186, btch:  31 usd: 172
CPU   24: hi:  186, btch:  31 usd: 177
CPU   25: hi:  186, btch:  31 usd: 171
CPU   26: hi:  186, btch:  31 usd: 157
CPU   27: hi:  186, btch:  31 usd: 171
CPU   28: hi:  186, btch:  31 usd: 182
CPU   29: hi:  186, btch:  31 usd: 183
CPU   30: hi:  186, btch:  31 usd:  40
CPU   31: hi:  186, btch:  31 usd: 157
CPU   32: hi:  186, btch:  31 usd:  76
CPU   33: hi:  186, btch:  31 usd: 157
CPU   34: hi:  186, btch:  31 usd:  63
CPU   35: hi:  186, btch:  31 usd:  62
CPU   36: hi:  186, btch:  31 usd:  58
CPU   37: hi:  186, btch:  31 usd:  36
CPU   38: hi:  186, btch:  31 usd:  19
CPU   39: hi:  186, btch:  31 usd:  47
active_anon:6762239 inactive_anon:12245334 isolated_anon:0
 active_file:10705451 inactive_file:11321321 isolated_file:0
 unevictable:5516901 dirty:457441 writeback:0 unstable:0
 free:1028680 slab_reclaimable:3791349 slab_unreclaimable:13461537
 mapped:1567688 shmem:904717 pagetables:362061 bounce:0
 free_cma:0
Node 0 DMA free:15532kB min:8kB low:8kB high:12kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15976kB managed:15892kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
lowmem_reserve[]: 0 1668 128642 128642
Node 0 DMA32 free:509204kB min:1164kB low:1452kB high:1744kB active_anon:6016kB inactive_anon:13164kB active_file:2584kB inactive_file:5756kB unevictable:1112kB isolated(anon):0kB isolated(file):0kB present:2045980kB managed:1708904kB mlocked:1224kB dirty:20kB writeback:0kB mapped:4164kB shmem:3900kB slab_reclaimable:463020kB slab_unreclaimable:671072kB kernel_stack:1224kB pagetables:4268kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 126973 126973
Node 0 Normal free:189488kB min:88804kB low:111004kB high:133204kB active_anon:16411204kB inactive_anon:24056744kB active_file:19949588kB inactive_file:22435040kB unevictable:8645768kB isolated(anon):0kB isolated(file):0kB present:132120576kB managed:130020968kB mlocked:8657300kB dirty:1773000kB writeback:0kB mapped:2878728kB shmem:1624252kB slab_reclaimable:6834156kB slab_unreclaimable:29014116kB kernel_stack:65736kB pagetables:711944kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 0 0
Node 1 Normal free:3393536kB min:90240kB low:112800kB high:135360kB active_anon:10638288kB inactive_anon:24911428kB active_file:22869632kB inactive_file:22844488kB unevictable:13420724kB isolated(anon):0kB isolated(file):0kB present:134217728kB managed:132117884kB mlocked:13427472kB dirty:56744kB writeback:0kB mapped:3387860kB shmem:1990716kB slab_reclaimable:7868220kB slab_unreclaimable:24160960kB kernel_stack:90600kB pagetables:731280kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 0 0
Node 0 DMA: 1*4kB (U) 1*8kB (U) 0*16kB 1*32kB (U) 0*64kB 1*128kB (U) 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (U) 3*4096kB (MR) = 15532kB
Node 0 DMA32: 612*4kB (UEM) 1081*8kB (UEM) 295*16kB (UEM) 412*32kB (UEM) 288*64kB (UEM) 118*128kB (UEM) 63*256kB (UEM) 49*512kB (UEM) 30*1024kB (UEM) 29*2048kB (UEM) 77*4096kB (UMR) = 509256kB
Node 0 Normal: 44891*4kB (UE) 0*8kB 0*16kB 5*32kB (R) 4*64kB (R) 2*128kB (R) 1*256kB (R) 1*512kB (R) 1*1024kB (R) 0*2048kB 1*4096kB (R) = 186124kB
Node 1 Normal: 467218*4kB (UEM) 145540*8kB (UEM) 18995*16kB (UEM) 1482*32kB (UMR) 5*64kB (R) 1*128kB (R) 2*256kB (R) 1*512kB (R) 1*1024kB (R) 0*2048kB 1*4096kB (R) = 3391128kB
23967743 total pagecache pages
1034858 pages in swap cache
Swap cache stats: add 154167590, delete 153132732, find 2698616740/2708213552
Free swap  = 16464476kB
Total swap = 41943036kB
67100065 pages RAM
0 pages HighMem/MovableOnly
524961 pages reserved
--
To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html



[Index of Archives]     [Reiser Filesystem Development]     [Ceph FS]     [Kernel Newbies]     [Security]     [Netfilter]     [Bugtraq]     [Linux FS]     [Yosemite National Park]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Samba]     [Device Mapper]     [Linux Media]

  Powered by Linux