From: Jan Kara <jack@suse.cz>
Subject: Re: Yet another ext4/jbd2 lockup
Date: Mon, 10 Aug 2015 15:58:42 +0200
Message-ID: <20150810135842.GE3768@quack.suse.cz>
References: <55B8D61E.7090609@kyup.com>
 <20150803151525.GE9657@quack.suse.cz>
 <55C4616A.10100@kyup.com>
Mime-Version: 1.0
Content-Type: multipart/mixed; boundary="OgqxwSJOaUobr8KG"
Cc: Jan Kara <jack@suse.cz>, linux-ext4@vger.kernel.org,
	Theodore Ts'o <tytso@mit.edu>, Marian Marinov <mm@1h.com>
To: Nikolay Borisov <kernel@kyup.com>
Return-path: <linux-ext4-owner@vger.kernel.org>
Received: from mx2.suse.de ([195.135.220.15]:57034 "EHLO mx2.suse.de"
	rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP
	id S1752998AbbHJN6p (ORCPT <rfc822;linux-ext4@vger.kernel.org>);
	Mon, 10 Aug 2015 09:58:45 -0400
Content-Disposition: inline
In-Reply-To: <55C4616A.10100@kyup.com>
Sender: linux-ext4-owner@vger.kernel.org
List-ID: <linux-ext4.vger.kernel.org>


--OgqxwSJOaUobr8KG
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

  Hello,

On Fri 07-08-15 10:42:34, Nikolay Borisov wrote:
> I have attached an XZ archive of the dumpe2fs command.

Thanks. So I don't see anything suspicious in the dumpe2fs. I've looked
again at the code and I still don't see how handle can be marked as sync in
ext4_writepages(). I wrote attached patch to dump stack in case this
happens. The dumping doesn't trigger for me. Can you reproduce the problem?
Can you run a kernel with the attached patch applied and report stack dumps
appearing in the kernel log?

								Honza

> On 08/03/2015 06:15 PM, Jan Kara wrote:
> >   Hello,
> > 
> > On Wed 29-07-15 16:33:18, Nikolay Borisov wrote:
> >> 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
> > 
> > So this is waiting to start a new transaction in the journal.
> > 
> >> Sampling echo "w" > /proc/sysrq-trigger I found some other 
> > 
> > You can just attach full output from the above command. That way we can be
> > sure we see all the pieces...
> > 
> >> 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
> > 
> > So jbd2 thread is waiting for page lock. Interesting...
> > 
> >> 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
> > 
> > And this is likely the culprit - flusher thread is waiting for journal
> > commit from jbd2_journal_stop() at which point it may be holding page locks
> > which are blocking jbd2 thread. Now waiting from transaction commit from
> > jbd2_journal_stop() is really unexpected. That happens only if the
> > handle was a sync one and the only way I can see handle becoming a sync one
> > from a writeback path is when this would be the first file over 4 GB in the
> > filesystem which looks really unlikely... Can you post output of dumpe2fs
> > for the filesystem? Thanks!
> > 
> > 								Honza
> > 
> >> 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@vger.kernel.org
> >> More majordomo info at  http://vger.kernel.org/majordomo-info.html


-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

--OgqxwSJOaUobr8KG
Content-Type: text/x-patch; charset=us-ascii
Content-Disposition: attachment; filename="0001-jbd2-Debug-sync-handle-from-writeback.patch"

>From 1d98bc7c3d2940c25ac2ca0cb0a3f6101a942671 Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.com>
Date: Mon, 10 Aug 2015 11:06:11 +0200
Subject: [PATCH] jbd2: Debug sync handle from writeback

Signed-off-by: Jan Kara <jack@suse.com>
---
 fs/ext4/ext4_jbd2.h | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/fs/ext4/ext4_jbd2.h b/fs/ext4/ext4_jbd2.h
index 9c5b49fb281e..0a63b49caf4e 100644
--- a/fs/ext4/ext4_jbd2.h
+++ b/fs/ext4/ext4_jbd2.h
@@ -278,8 +278,13 @@ static inline int ext4_handle_valid(handle_t *handle)
 
 static inline void ext4_handle_sync(handle_t *handle)
 {
-	if (ext4_handle_valid(handle))
+	if (ext4_handle_valid(handle)) {
 		handle->h_sync = 1;
+		if (handle->h_type == EXT4_HT_WRITE_PAGE) {
+			printk(KERN_ERR "ext4: Writeback handle is sync!\n");
+			dump_stack();
+		}
+	}
 }
 
 static inline int ext4_handle_is_aborted(handle_t *handle)
-- 
2.1.4


--OgqxwSJOaUobr8KG--