From: Dave Chinner <david@fromorbit.com>
To: Wu Fengguang <fengguang.wu@intel.com>
Cc: Andrew Morton <akpm@linux-foundation.org>,
Mel Gorman <mel@csn.ul.ie>,
Linux Kernel List <linux-kernel@vger.kernel.org>,
"linux-mm@kvack.org" <linux-mm@kvack.org>,
Rik van Riel <riel@redhat.com>,
Johannes Weiner <hannes@cmpxchg.org>,
Minchan Kim <minchan.kim@gmail.com>,
Christoph Lameter <cl@linux-foundation.org>,
KAMEZAWA Hiroyuki <kamezawa.hiroyu@jp.fujitsu.com>,
KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>,
David Rientjes <rientjes@google.com>
Subject: Re: [PATCH 3/3] mm: page allocator: Drain per-cpu lists after direct reclaim allocation fails
Date: Mon, 6 Sep 2010 14:02:43 +1000 [thread overview]
Message-ID: <20100906040243.GA7362@dastard> (raw)
In-Reply-To: <20100905134554.GA7083@localhost>
On Sun, Sep 05, 2010 at 09:45:54PM +0800, Wu Fengguang wrote:
> [restoring CC list]
>
> On Sun, Sep 05, 2010 at 09:14:47PM +0800, Dave Chinner wrote:
> > On Sun, Sep 05, 2010 at 02:05:39PM +0800, Wu Fengguang wrote:
> > > On Sun, Sep 05, 2010 at 10:15:55AM +0800, Dave Chinner wrote:
> > > > On Sun, Sep 05, 2010 at 09:54:00AM +0800, Wu Fengguang wrote:
> > > > > Dave, could you post (publicly) the kconfig and /proc/vmstat?
> > > > >
> > > > > I'd like to check if you have swap or memory compaction enabled..
> > > >
> > > > Swap is enabled - it has 512MB of swap space:
> > > >
> > > > $ free
> > > > total used free shared buffers cached
> > > > Mem: 4054304 100928 3953376 0 4096 43108
> > > > -/+ buffers/cache: 53724 4000580
> > > > Swap: 497976 0 497976
> > >
> > > It looks swap is not used at all.
> >
> > It isn't 30s after boot, abut I haven't checked after a livelock.
>
> That's fine. I see in your fs_mark-wedge-1.png that there are no
> read/write IO at all when CPUs are 100% busy. So there should be no
> swap IO at "livelock" time.
>
> > > > And memory compaction is not enabled:
> > > >
> > > > $ grep COMPACT .config
> > > > # CONFIG_COMPACTION is not set
>
> Memory compaction is not likely the cause too. It will only kick in for
> order > 3 allocations.
>
> > > >
> > > > The .config is pretty much a 'make defconfig' and then enabling XFS and
> > > > whatever debug I need (e.g. locking, memleak, etc).
> > >
> > > Thanks! The problem seems hard to debug -- you cannot login at all
> > > when it is doing lock contentions, so cannot get sysrq call traces.
> >
> > Well, I don't know whether it is lock contention at all. The sets of
> > traces I have got previously have shown backtraces on all CPUs in
> > direct reclaim with several in draining queues, but no apparent lock
> > contention.
>
> That's interesting. Do you still have the full backtraces?
Just saw one when testing some new code with CONFIG_XFS_DEBUG
enabled. The act of running 'echo t > /proc/sysrq-trigger' seems to
have got the machine unstuck, so I'm not sure if the traces are
completely representative of the livelock state. however, here are
the fs_mark processes:
[ 596.628086] fs_mark R running task 0 2373 2163 0x00000008
[ 596.628086] 0000000000000000 ffffffff81bb8610 00000000000008fc 0000000000000002
[ 596.628086] 0000000000000000 0000000000000296 0000000000000297 ffffffffffffff10
[ 596.628086] ffffffff810b48c2 0000000000000010 0000000000000202 ffff880116b61798
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff810b48c2>] ? smp_call_function_many+0x1a2/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2374 2163 0x00000000
[ 596.628086] 0000000000000000 0000000000000002 ffff88011ad619b0 ffff88011fc050c0
[ 596.628086] ffff88011ad619e8 ffffffff8113dce6 ffff88011fc028c0 ffff88011fc02900
[ 596.628086] ffff88011ad619e8 0000025000000000 ffff880100001c08 0000001000000000
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2375 2163 0x00000000
[ 596.628086] ffff8801198f96f8 ffff880100000000 0000000000000001 0000000000000002
[ 596.628086] ffff8801198f9708 ffffffff8110758a 0000000001320122 0000000000000002
[ 596.628086] ffff8801198f8000 ffff880100000000 0000000000000007 0000000000000250
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8110758a>] ? zone_watermark_ok+0x2a/0xf0
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff810b48c6>] ? smp_call_function_many+0x1a6/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2376 2163 0x00000000
[ 596.628086] ffff88011d303708 ffffffff8110758a 0000000001320122 0000000000000002
[ 596.628086] ffff88011d302000 ffff880100000000 0000000000000007 0000000000000250
[ 596.628086] ffffffff8103694e ffff88011d3037d8 ffff88011c9808f8 0000000000000001
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8110758a>] ? zone_watermark_ok+0x2a/0xf0
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff810b48c2>] ? smp_call_function_many+0x1a2/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2377 2163 0x00000008
[ 596.628086] 0000000000000000 ffff880103dd9528 ffffffff813f2deb 000000000000003f
[ 596.628086] ffff88011c9806e0 ffff880103dd95a4 ffff880103dd9518 ffffffff813fd98e
[ 596.628086] ffff880103dd95a4 ffff88011ce51800 ffff880103dd9528 ffffffff8180722e
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff813f2deb>] ? radix_tree_gang_lookup_tag+0x8b/0x100
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[ 596.628086] [<ffffffff8131f318>] ? xfs_inode_ag_iter_next_pag+0x108/0x110
[ 596.628086] [<ffffffff8132018c>] ? xfs_reclaim_inode_shrink+0x4c/0x90
[ 596.628086] [<ffffffff81119d02>] ? zone_nr_free_pages+0xa2/0xc0
[ 596.628086] [<ffffffff8110758a>] ? zone_watermark_ok+0x2a/0xf0
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff810b48c2>] ? smp_call_function_many+0x1a2/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130b2f9>] ? xfs_dir_ialloc+0x139/0x340
[ 596.628086] [<ffffffff812f9cc7>] ? xfs_log_reserve+0x167/0x1e0
[ 596.628086] [<ffffffff8130d35c>] ? xfs_create+0x3dc/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2378 2163 0x00000000
[ 596.628086] ffff880103d53a78 0000000000000086 ffff8800a3fc6cc0 0000000000000caf
[ 596.628086] ffff880103d53a18 00000000000135c0 ffff88011f119040 00000000000135c0
[ 596.628086] ffff88011f1193a8 ffff880103d53fd8 ffff88011f1193b0 ffff880103d53fd8
[ 596.628086] Call Trace8f/0xe0
[ 596.628086] [<ffffffff810773ca>] __cond_resched+0x2a/0x40
[ 596.628086] [<ffffffff8113e4f8>] ? __kmalloc+0x48/0x230
[ 596.628086] [<ffffffff81804d90>] _cond_resched+0x30/0x40
[ 596.628086] [<ffffffff8113e5e1>] __kmalloc+0x131/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff81306b75>] xfs_trans_alloc_log_vecs+0xa5/0xe0
[ 596.628086] [<ffffffff813082b8>] _xfs_trans_commit+0x138/0x2f0
[ 596.628086] [<ffffffff8130d50e>] xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2379 2163 0x00000000
[ 596.628086] ffff88011f0ddd80 ffff880103da5eb8 000001b600008243 ffff88008652ca80
[ 596.628086] ffffffff8115f8fa 00007fff71ba9370 ffff880000000005 ffff88011e35cb80
[ 596.628086] ffff880076835ed0 ffff880103da5f18 0000000000000005 ffff88006d30b000
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2380 2163 0x00000000
[ 596.628086] 00000000000008fc 0000000000000001 0000000000000000 0000000000000296
[ 596.628086] 0000000000000293 ffffffffffffff10 ffffffff810b48c2 0000000000000010
[ 596.628086] 0000000000000202 ffff880103c05798 0000000000000018 ffffffff810b48a5
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff810b48c2>] ? smp_call_function_many+0x1a2/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
and the kswapd thread:
[ 596.628086] kswapd0 R running task 0 547 2 0x00000000
[ 596.628086] ffff88011e78fbc0 0000000000000046 0000000000000000 ffffffff8103694e
[ 596.628086] ffff88011e78fbf0 00000000000135c0 ffff88011f17c040 00000000000135c0
[ 596.628086] ffff88011f17c3a8 ffff88011e78ffd8 ffff88011f17c3b0 ffff88011e78ffd8
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff810773ca>] __cond_resched+0x2a/0x40
[ 596.628086] [<ffffffff81077422>] __cond_resched_lock+0x42/0x60
[ 596.628086] [<ffffffff811593a0>] __shrink_dcache_sb+0xf0/0x380
[ 596.628086] [<ffffffff811597c6>] shrink_dcache_memory+0x176/0x200
[ 596.628086] [<ffffffff81110bf4>] shrink_slab+0x124/0x180
[ 596.628086] [<ffffffff811125d2>] balance_pgdat+0x2e2/0x540
[ 596.628086] [<ffffffff8111295d>] kswapd+0x12d/0x390
[ 596.628086] [<ffffffff8109e8c0>] ? autoremove_wake_function+0x0/0x40
[ 596.628086] [<ffffffff81112830>] ? kswapd+0x0/0x390
[ 596.628086] [<ffffffff8109e396>] kthread+0x96/0xa0
[ 596.628086] [<ffffffff81036da4>] kernel_thread_helper+0x4/0x10
[ 596.628086] [<ffffffff8109e300>] ? kthread+0x0/0xa0
[ 596.628086] [<ffffffff81036da0>] ? kernel_thread_helper+0x0/0x10
I just went to grab the CAL counters, and found the system in
another livelock. This time I managed to start the sysrq-trigger
dump while the livelock was in progress - I basіcally got one shot
at a command before everything stopped responding. Now I'm waiting
for the livelock to pass.... 5min.... the fs_mark workload
has stopped (ctrl-c finally responded), still livelocked....
10min.... 15min.... 20min.... OK, back now.
Interesting - all the fs_mark processes are in D state waiting on IO
completion processing. And the only running processes are the
kworker threads, which are all processing either vmstat updates
(3 CPUs):
kworker/6:1 R running task 0 376 2 0x00000000
ffff88011f255cf0 0000000000000046 ffff88011f255c90 ffffffff813fda34
ffff88003c969588 00000000000135c0 ffff88011f27c7f0 00000000000135c0
ffff88011f27cb58 ffff88011f255fd8 ffff88011f27cb60 ffff88011f255fd8
Call Trace:
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff810773ca>] __cond_resched+0x2a/0x40
[<ffffffff81804d90>] _cond_resched+0x30/0x40
[<ffffffff8111ab12>] refresh_cpu_vm_stats+0xc2/0x160
[<ffffffff8111abb0>] ? vmstat_update+0x0/0x40
[<ffffffff8111abc6>] vmstat_update+0x16/0x40
[<ffffffff810978a0>] process_one_work+0x130/0x470
[<ffffffff81099e72>] worker_thread+0x172/0x3f0
[<ffffffff81099d00>] ? worker_thread+0x0/0x3f0
[<ffffffff8109e396>] kthread+0x96/0xa0
[<ffffffff81036da4>] kernel_thread_helper+0x4/0x10
[<ffffffff8109e300>] ? kthread+0x0/0xa0
[<ffffffff81036da0>] ? kernel_thread_helper+0x0/0x10
Or doing inode IO completion processing:
kworker/7:1 R running task 0 377 2 0x00000000
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] ffffffffffffff10 0000000000000001 ffffffffffffff10 ffffffff813f8062
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] 0000000000000010 0000000000000202 ffff88011f0ffc80 ffffffff813f8067
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] 00000000000ac613 ffff88011ba08280 00000000871803d0 0000000000000001
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] Call Trace:
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813f8062>] ? delay_tsc+0x22/0x80
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813f808a>] ? delay_tsc+0x4a/0x80
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813f7fdf>] ? __delay+0xf/0x20
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813fdb03>] ? do_raw_spin_lock+0x123/0x160
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff818072be>] ? _raw_spin_lock+0xe/0x10
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff812f0244>] ? xfs_iflush_done+0x84/0xb0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813157c0>] ? xfs_buf_iodone_work+0x0/0x100
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff812cee54>] ? xfs_buf_do_callbacks+0x54/0x70
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff812cf0c0>] ? xfs_buf_iodone_callbacks+0x1a0/0x2a0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813157c0>] ? xfs_buf_iodone_work+0x0/0x100
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81315805>] ? xfs_buf_iodone_work+0x45/0x100
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813157c0>] ? xfs_buf_iodone_work+0x0/0x100
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff810978a0>] ? process_one_work+0x130/0x470
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81099e72>] ? worker_thread+0x172/0x3f0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81099d00>] ? worker_thread+0x0/0x3f0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff8109e396>] ? kthread+0x96/0xa0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81036da4>] ? kernel_thread_helper+0x4/0x10
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff8109e300>] ? kthread+0x0/0xa0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81036da0>] ? kernel_thread_helper+0x0/0x10
It looks like there is spinlock contention occurring here on the xfs
AIL lock, so I'll need to look into this further. A second set of
traces I got during the livelock also showed this:
fs_mark R running task 0 2713 1 0x00000004
ffff88011851b518 ffffffff81804669 ffff88011851b4d8 ffff880100000700
0000000000000000 00000000000135c0 ffff88011f05b7f0 00000000000135c0
ffff88011f05bb58 ffff88011851bfd8 ffff88011f05bb60 ffff88011851bfd8
Call Trace:
[<ffffffff81804669>] ? schedule+0x3c9/0x9f0
[<ffffffff81805235>] schedule_timeout+0x1d5/0x2a0
[<ffffffff81119d02>] ? zone_nr_free_pages+0xa2/0xc0
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff8110758a>] ? zone_watermark_ok+0x2a/0xf0
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff81807275>] ? _raw_spin_lock_irq+0x15/0x20
[<ffffffff81806638>] __down+0x78/0xb0
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff8113d8e6>] cache_alloc_refill+0x1c6/0x2b0
[<ffffffff813fda34>] do_raw_spin_lock+0x54/0x160
[<ffffffff812e9672>] ? xfs_iext_bno_to_irec+0xb2/0x100
[<ffffffff811022ce>] ? find_get_page+0x1e/0xa0
[<ffffffff81103dd7>] ? find_lock_page+0x37/0x80
[<ffffffff8110438f>] ? find_or_create_page+0x3f/0xb0
[<ffffffff811025e7>] ? unlock_page+0x27/0x30
[<ffffffff81315167>] ? _xfs_buf_lookup_pages+0x297/0x370
[<ffffffff813f808a>] ? delay_tsc+0x4a/0x80
[<ffffffff813f7fdf>] ? __delay+0xf/0x20
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff81109e69>] ? free_pcppages_bulk+0x369/0x400
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff81109e69>] ? free_pcppages_bulk+0x369/0x400
[<ffffffff8110a508>] ? __pagevec_free+0x58/0xb0
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff810af53c>] ? debug_mutex_add_waiter+0x2c/0x70
[<ffffffff81805d70>] ? __mutex_lock_slowpath+0x1e0/0x280
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff810fdac2>] ? perf_event_exit_task+0x32/0x160
[<ffffffff813fd772>] ? do_raw_write_lock+0x42/0xa0
[<ffffffff81807015>] ? _raw_write_lock_irq+0x15/0x20
[<ffffffff81082315>] ? do_exit+0x195/0x7c0
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff81082991>] ? do_group_exit+0x51/0xc0
[<ffffffff81092d8c>] ? get_signal_to_deliver+0x27c/0x430
[<ffffffff810352b5>] ? do_signal+0x75/0x7c0
[<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff81035a65>] ? do_notify_resume+0x65/0x90
[<ffffffff81036283>] ? int_signal+0x12/0x17
Because I tried to ctrl-c the fs_mark workload. All those lock
traces on the stack aren't related to XFS, so I'm wondering exactly
where they have come from....
Finally, /proc/interrupts shows:
CAL: 12156 12039 12676 12478 12919 12177 12767 12460 Function call interrupts
Which shows that this wasn't an IPI storm that caused this
particular livelock.
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
WARNING: multiple messages have this Message-ID (diff)
From: Dave Chinner <david@fromorbit.com>
To: Wu Fengguang <fengguang.wu@intel.com>
Cc: Andrew Morton <akpm@linux-foundation.org>,
Mel Gorman <mel@csn.ul.ie>,
Linux Kernel List <linux-kernel@vger.kernel.org>,
"linux-mm@kvack.org" <linux-mm@kvack.org>,
Rik van Riel <riel@redhat.com>,
Johannes Weiner <hannes@cmpxchg.org>,
Minchan Kim <minchan.kim@gmail.com>,
Christoph Lameter <cl@linux-foundation.org>,
KAMEZAWA Hiroyuki <kamezawa.hiroyu@jp.fujitsu.com>,
KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>,
David Rientjes <rientjes@google.com>
Subject: Re: [PATCH 3/3] mm: page allocator: Drain per-cpu lists after direct reclaim allocation fails
Date: Mon, 6 Sep 2010 14:02:43 +1000 [thread overview]
Message-ID: <20100906040243.GA7362@dastard> (raw)
In-Reply-To: <20100905134554.GA7083@localhost>
On Sun, Sep 05, 2010 at 09:45:54PM +0800, Wu Fengguang wrote:
> [restoring CC list]
>
> On Sun, Sep 05, 2010 at 09:14:47PM +0800, Dave Chinner wrote:
> > On Sun, Sep 05, 2010 at 02:05:39PM +0800, Wu Fengguang wrote:
> > > On Sun, Sep 05, 2010 at 10:15:55AM +0800, Dave Chinner wrote:
> > > > On Sun, Sep 05, 2010 at 09:54:00AM +0800, Wu Fengguang wrote:
> > > > > Dave, could you post (publicly) the kconfig and /proc/vmstat?
> > > > >
> > > > > I'd like to check if you have swap or memory compaction enabled..
> > > >
> > > > Swap is enabled - it has 512MB of swap space:
> > > >
> > > > $ free
> > > > total used free shared buffers cached
> > > > Mem: 4054304 100928 3953376 0 4096 43108
> > > > -/+ buffers/cache: 53724 4000580
> > > > Swap: 497976 0 497976
> > >
> > > It looks swap is not used at all.
> >
> > It isn't 30s after boot, abut I haven't checked after a livelock.
>
> That's fine. I see in your fs_mark-wedge-1.png that there are no
> read/write IO at all when CPUs are 100% busy. So there should be no
> swap IO at "livelock" time.
>
> > > > And memory compaction is not enabled:
> > > >
> > > > $ grep COMPACT .config
> > > > # CONFIG_COMPACTION is not set
>
> Memory compaction is not likely the cause too. It will only kick in for
> order > 3 allocations.
>
> > > >
> > > > The .config is pretty much a 'make defconfig' and then enabling XFS and
> > > > whatever debug I need (e.g. locking, memleak, etc).
> > >
> > > Thanks! The problem seems hard to debug -- you cannot login at all
> > > when it is doing lock contentions, so cannot get sysrq call traces.
> >
> > Well, I don't know whether it is lock contention at all. The sets of
> > traces I have got previously have shown backtraces on all CPUs in
> > direct reclaim with several in draining queues, but no apparent lock
> > contention.
>
> That's interesting. Do you still have the full backtraces?
Just saw one when testing some new code with CONFIG_XFS_DEBUG
enabled. The act of running 'echo t > /proc/sysrq-trigger' seems to
have got the machine unstuck, so I'm not sure if the traces are
completely representative of the livelock state. however, here are
the fs_mark processes:
[ 596.628086] fs_mark R running task 0 2373 2163 0x00000008
[ 596.628086] 0000000000000000 ffffffff81bb8610 00000000000008fc 0000000000000002
[ 596.628086] 0000000000000000 0000000000000296 0000000000000297 ffffffffffffff10
[ 596.628086] ffffffff810b48c2 0000000000000010 0000000000000202 ffff880116b61798
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff810b48c2>] ? smp_call_function_many+0x1a2/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2374 2163 0x00000000
[ 596.628086] 0000000000000000 0000000000000002 ffff88011ad619b0 ffff88011fc050c0
[ 596.628086] ffff88011ad619e8 ffffffff8113dce6 ffff88011fc028c0 ffff88011fc02900
[ 596.628086] ffff88011ad619e8 0000025000000000 ffff880100001c08 0000001000000000
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2375 2163 0x00000000
[ 596.628086] ffff8801198f96f8 ffff880100000000 0000000000000001 0000000000000002
[ 596.628086] ffff8801198f9708 ffffffff8110758a 0000000001320122 0000000000000002
[ 596.628086] ffff8801198f8000 ffff880100000000 0000000000000007 0000000000000250
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8110758a>] ? zone_watermark_ok+0x2a/0xf0
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff810b48c6>] ? smp_call_function_many+0x1a6/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2376 2163 0x00000000
[ 596.628086] ffff88011d303708 ffffffff8110758a 0000000001320122 0000000000000002
[ 596.628086] ffff88011d302000 ffff880100000000 0000000000000007 0000000000000250
[ 596.628086] ffffffff8103694e ffff88011d3037d8 ffff88011c9808f8 0000000000000001
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8110758a>] ? zone_watermark_ok+0x2a/0xf0
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff810b48c2>] ? smp_call_function_many+0x1a2/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2377 2163 0x00000008
[ 596.628086] 0000000000000000 ffff880103dd9528 ffffffff813f2deb 000000000000003f
[ 596.628086] ffff88011c9806e0 ffff880103dd95a4 ffff880103dd9518 ffffffff813fd98e
[ 596.628086] ffff880103dd95a4 ffff88011ce51800 ffff880103dd9528 ffffffff8180722e
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff813f2deb>] ? radix_tree_gang_lookup_tag+0x8b/0x100
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[ 596.628086] [<ffffffff8131f318>] ? xfs_inode_ag_iter_next_pag+0x108/0x110
[ 596.628086] [<ffffffff8132018c>] ? xfs_reclaim_inode_shrink+0x4c/0x90
[ 596.628086] [<ffffffff81119d02>] ? zone_nr_free_pages+0xa2/0xc0
[ 596.628086] [<ffffffff8110758a>] ? zone_watermark_ok+0x2a/0xf0
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff810b48c2>] ? smp_call_function_many+0x1a2/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130b2f9>] ? xfs_dir_ialloc+0x139/0x340
[ 596.628086] [<ffffffff812f9cc7>] ? xfs_log_reserve+0x167/0x1e0
[ 596.628086] [<ffffffff8130d35c>] ? xfs_create+0x3dc/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2378 2163 0x00000000
[ 596.628086] ffff880103d53a78 0000000000000086 ffff8800a3fc6cc0 0000000000000caf
[ 596.628086] ffff880103d53a18 00000000000135c0 ffff88011f119040 00000000000135c0
[ 596.628086] ffff88011f1193a8 ffff880103d53fd8 ffff88011f1193b0 ffff880103d53fd8
[ 596.628086] Call Trace8f/0xe0
[ 596.628086] [<ffffffff810773ca>] __cond_resched+0x2a/0x40
[ 596.628086] [<ffffffff8113e4f8>] ? __kmalloc+0x48/0x230
[ 596.628086] [<ffffffff81804d90>] _cond_resched+0x30/0x40
[ 596.628086] [<ffffffff8113e5e1>] __kmalloc+0x131/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff81306b75>] xfs_trans_alloc_log_vecs+0xa5/0xe0
[ 596.628086] [<ffffffff813082b8>] _xfs_trans_commit+0x138/0x2f0
[ 596.628086] [<ffffffff8130d50e>] xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2379 2163 0x00000000
[ 596.628086] ffff88011f0ddd80 ffff880103da5eb8 000001b600008243 ffff88008652ca80
[ 596.628086] ffffffff8115f8fa 00007fff71ba9370 ffff880000000005 ffff88011e35cb80
[ 596.628086] ffff880076835ed0 ffff880103da5f18 0000000000000005 ffff88006d30b000
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
[ 596.628086] fs_mark R running task 0 2380 2163 0x00000000
[ 596.628086] 00000000000008fc 0000000000000001 0000000000000000 0000000000000296
[ 596.628086] 0000000000000293 ffffffffffffff10 ffffffff810b48c2 0000000000000010
[ 596.628086] 0000000000000202 ffff880103c05798 0000000000000018 ffffffff810b48a5
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff810b48c2>] ? smp_call_function_many+0x1a2/0x210
[ 596.628086] [<ffffffff810b48a5>] ? smp_call_function_many+0x185/0x210
[ 596.628086] [<ffffffff81109ff0>] ? drain_local_pages+0x0/0x20
[ 596.628086] [<ffffffff810b4952>] ? smp_call_function+0x22/0x30
[ 596.628086] [<ffffffff81084934>] ? on_each_cpu+0x24/0x50
[ 596.628086] [<ffffffff81108a8c>] ? drain_all_pages+0x1c/0x20
[ 596.628086] [<ffffffff81108fad>] ? __alloc_pages_nodemask+0x42d/0x700
[ 596.628086] [<ffffffff8113d0f2>] ? kmem_getpages+0x62/0x160
[ 596.628086] [<ffffffff8113dce6>] ? fallback_alloc+0x196/0x240
[ 596.628086] [<ffffffff8113da68>] ? ____cache_alloc_node+0x98/0x180
[ 596.628086] [<ffffffff8113e643>] ? __kmalloc+0x193/0x230
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131083f>] ? kmem_alloc+0x8f/0xe0
[ 596.628086] [<ffffffff8131092e>] ? kmem_zalloc+0x1e/0x50
[ 596.628086] [<ffffffff812fac80>] ? xfs_log_commit_cil+0x500/0x590
[ 596.628086] [<ffffffff81310943>] ? kmem_zalloc+0x33/0x50
[ 596.628086] [<ffffffff813082d6>] ? _xfs_trans_commit+0x156/0x2f0
[ 596.628086] [<ffffffff8130d50e>] ? xfs_create+0x58e/0x700
[ 596.628086] [<ffffffff8131c587>] ? xfs_vn_mknod+0xa7/0x1c0
[ 596.628086] [<ffffffff8131c6d0>] ? xfs_vn_create+0x10/0x20
[ 596.628086] [<ffffffff81151f48>] ? vfs_create+0xb8/0xf0
[ 596.628086] [<ffffffff8115273c>] ? do_last+0x4dc/0x5d0
[ 596.628086] [<ffffffff81154937>] ? do_filp_open+0x207/0x5e0
[ 596.628086] [<ffffffff8115b7bc>] ? d_lookup+0x3c/0x60
[ 596.628086] [<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[ 596.628086] [<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[ 596.628086] [<ffffffff8115f8fa>] ? alloc_fd+0xfa/0x140
[ 596.628086] [<ffffffff811448a5>] ? do_sys_open+0x65/0x130
[ 596.628086] [<ffffffff811449b0>] ? sys_open+0x20/0x30
[ 596.628086] [<ffffffff81036032>] ? system_call_fastpath+0x16/0x1b
and the kswapd thread:
[ 596.628086] kswapd0 R running task 0 547 2 0x00000000
[ 596.628086] ffff88011e78fbc0 0000000000000046 0000000000000000 ffffffff8103694e
[ 596.628086] ffff88011e78fbf0 00000000000135c0 ffff88011f17c040 00000000000135c0
[ 596.628086] ffff88011f17c3a8 ffff88011e78ffd8 ffff88011f17c3b0 ffff88011e78ffd8
[ 596.628086] Call Trace:
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff8103694e>] ? apic_timer_interrupt+0xe/0x20
[ 596.628086] [<ffffffff810773ca>] __cond_resched+0x2a/0x40
[ 596.628086] [<ffffffff81077422>] __cond_resched_lock+0x42/0x60
[ 596.628086] [<ffffffff811593a0>] __shrink_dcache_sb+0xf0/0x380
[ 596.628086] [<ffffffff811597c6>] shrink_dcache_memory+0x176/0x200
[ 596.628086] [<ffffffff81110bf4>] shrink_slab+0x124/0x180
[ 596.628086] [<ffffffff811125d2>] balance_pgdat+0x2e2/0x540
[ 596.628086] [<ffffffff8111295d>] kswapd+0x12d/0x390
[ 596.628086] [<ffffffff8109e8c0>] ? autoremove_wake_function+0x0/0x40
[ 596.628086] [<ffffffff81112830>] ? kswapd+0x0/0x390
[ 596.628086] [<ffffffff8109e396>] kthread+0x96/0xa0
[ 596.628086] [<ffffffff81036da4>] kernel_thread_helper+0x4/0x10
[ 596.628086] [<ffffffff8109e300>] ? kthread+0x0/0xa0
[ 596.628086] [<ffffffff81036da0>] ? kernel_thread_helper+0x0/0x10
I just went to grab the CAL counters, and found the system in
another livelock. This time I managed to start the sysrq-trigger
dump while the livelock was in progress - I basN?cally got one shot
at a command before everything stopped responding. Now I'm waiting
for the livelock to pass.... 5min.... the fs_mark workload
has stopped (ctrl-c finally responded), still livelocked....
10min.... 15min.... 20min.... OK, back now.
Interesting - all the fs_mark processes are in D state waiting on IO
completion processing. And the only running processes are the
kworker threads, which are all processing either vmstat updates
(3 CPUs):
kworker/6:1 R running task 0 376 2 0x00000000
ffff88011f255cf0 0000000000000046 ffff88011f255c90 ffffffff813fda34
ffff88003c969588 00000000000135c0 ffff88011f27c7f0 00000000000135c0
ffff88011f27cb58 ffff88011f255fd8 ffff88011f27cb60 ffff88011f255fd8
Call Trace:
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff810773ca>] __cond_resched+0x2a/0x40
[<ffffffff81804d90>] _cond_resched+0x30/0x40
[<ffffffff8111ab12>] refresh_cpu_vm_stats+0xc2/0x160
[<ffffffff8111abb0>] ? vmstat_update+0x0/0x40
[<ffffffff8111abc6>] vmstat_update+0x16/0x40
[<ffffffff810978a0>] process_one_work+0x130/0x470
[<ffffffff81099e72>] worker_thread+0x172/0x3f0
[<ffffffff81099d00>] ? worker_thread+0x0/0x3f0
[<ffffffff8109e396>] kthread+0x96/0xa0
[<ffffffff81036da4>] kernel_thread_helper+0x4/0x10
[<ffffffff8109e300>] ? kthread+0x0/0xa0
[<ffffffff81036da0>] ? kernel_thread_helper+0x0/0x10
Or doing inode IO completion processing:
kworker/7:1 R running task 0 377 2 0x00000000
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] ffffffffffffff10 0000000000000001 ffffffffffffff10 ffffffff813f8062
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] 0000000000000010 0000000000000202 ffff88011f0ffc80 ffffffff813f8067
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] 00000000000ac613 ffff88011ba08280 00000000871803d0 0000000000000001
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] Call Trace:
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813f8062>] ? delay_tsc+0x22/0x80
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813f808a>] ? delay_tsc+0x4a/0x80
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813f7fdf>] ? __delay+0xf/0x20
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813fdb03>] ? do_raw_spin_lock+0x123/0x160
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff818072be>] ? _raw_spin_lock+0xe/0x10
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff812f0244>] ? xfs_iflush_done+0x84/0xb0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813157c0>] ? xfs_buf_iodone_work+0x0/0x100
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff812cee54>] ? xfs_buf_do_callbacks+0x54/0x70
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff812cf0c0>] ? xfs_buf_iodone_callbacks+0x1a0/0x2a0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813157c0>] ? xfs_buf_iodone_work+0x0/0x100
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81315805>] ? xfs_buf_iodone_work+0x45/0x100
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff813157c0>] ? xfs_buf_iodone_work+0x0/0x100
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff810978a0>] ? process_one_work+0x130/0x470
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81099e72>] ? worker_thread+0x172/0x3f0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81099d00>] ? worker_thread+0x0/0x3f0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff8109e396>] ? kthread+0x96/0xa0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81036da4>] ? kernel_thread_helper+0x4/0x10
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff8109e300>] ? kthread+0x0/0xa0
Sep 6 13:20:47 test-4 kernel: [ 2114.056017] [<ffffffff81036da0>] ? kernel_thread_helper+0x0/0x10
It looks like there is spinlock contention occurring here on the xfs
AIL lock, so I'll need to look into this further. A second set of
traces I got during the livelock also showed this:
fs_mark R running task 0 2713 1 0x00000004
ffff88011851b518 ffffffff81804669 ffff88011851b4d8 ffff880100000700
0000000000000000 00000000000135c0 ffff88011f05b7f0 00000000000135c0
ffff88011f05bb58 ffff88011851bfd8 ffff88011f05bb60 ffff88011851bfd8
Call Trace:
[<ffffffff81804669>] ? schedule+0x3c9/0x9f0
[<ffffffff81805235>] schedule_timeout+0x1d5/0x2a0
[<ffffffff81119d02>] ? zone_nr_free_pages+0xa2/0xc0
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff8110758a>] ? zone_watermark_ok+0x2a/0xf0
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff81807275>] ? _raw_spin_lock_irq+0x15/0x20
[<ffffffff81806638>] __down+0x78/0xb0
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff8113d8e6>] cache_alloc_refill+0x1c6/0x2b0
[<ffffffff813fda34>] do_raw_spin_lock+0x54/0x160
[<ffffffff812e9672>] ? xfs_iext_bno_to_irec+0xb2/0x100
[<ffffffff811022ce>] ? find_get_page+0x1e/0xa0
[<ffffffff81103dd7>] ? find_lock_page+0x37/0x80
[<ffffffff8110438f>] ? find_or_create_page+0x3f/0xb0
[<ffffffff811025e7>] ? unlock_page+0x27/0x30
[<ffffffff81315167>] ? _xfs_buf_lookup_pages+0x297/0x370
[<ffffffff813f808a>] ? delay_tsc+0x4a/0x80
[<ffffffff813f7fdf>] ? __delay+0xf/0x20
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff81109e69>] ? free_pcppages_bulk+0x369/0x400
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff81109e69>] ? free_pcppages_bulk+0x369/0x400
[<ffffffff8110a508>] ? __pagevec_free+0x58/0xb0
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff810af53c>] ? debug_mutex_add_waiter+0x2c/0x70
[<ffffffff81805d70>] ? __mutex_lock_slowpath+0x1e0/0x280
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff810fdac2>] ? perf_event_exit_task+0x32/0x160
[<ffffffff813fd772>] ? do_raw_write_lock+0x42/0xa0
[<ffffffff81807015>] ? _raw_write_lock_irq+0x15/0x20
[<ffffffff81082315>] ? do_exit+0x195/0x7c0
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff81082991>] ? do_group_exit+0x51/0xc0
[<ffffffff81092d8c>] ? get_signal_to_deliver+0x27c/0x430
[<ffffffff810352b5>] ? do_signal+0x75/0x7c0
[<ffffffff8105fc58>] ? pvclock_clocksource_read+0x58/0xd0
[<ffffffff813fda34>] ? do_raw_spin_lock+0x54/0x160
[<ffffffff813fd98e>] ? do_raw_spin_unlock+0x5e/0xb0
[<ffffffff8180722e>] ? _raw_spin_unlock+0xe/0x10
[<ffffffff81035a65>] ? do_notify_resume+0x65/0x90
[<ffffffff81036283>] ? int_signal+0x12/0x17
Because I tried to ctrl-c the fs_mark workload. All those lock
traces on the stack aren't related to XFS, so I'm wondering exactly
where they have come from....
Finally, /proc/interrupts shows:
CAL: 12156 12039 12676 12478 12919 12177 12767 12460 Function call interrupts
Which shows that this wasn't an IPI storm that caused this
particular livelock.
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
--
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/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
next prev parent reply other threads:[~2010-09-06 4:04 UTC|newest]
Thread overview: 104+ messages / expand[flat|nested] mbox.gz Atom feed top
2010-09-03 9:08 [PATCH 0/3] Reduce watermark-related problems with the per-cpu allocator V4 Mel Gorman
2010-09-03 9:08 ` Mel Gorman
2010-09-03 9:08 ` [PATCH 1/3] mm: page allocator: Update free page counters after pages are placed on the free list Mel Gorman
2010-09-03 9:08 ` Mel Gorman
2010-09-03 22:38 ` Andrew Morton
2010-09-03 22:38 ` Andrew Morton
2010-09-05 18:06 ` Mel Gorman
2010-09-05 18:06 ` Mel Gorman
2010-09-03 9:08 ` [PATCH 2/3] mm: page allocator: Calculate a better estimate of NR_FREE_PAGES when memory is low and kswapd is awake Mel Gorman
2010-09-03 9:08 ` Mel Gorman
2010-09-03 22:55 ` Andrew Morton
2010-09-03 22:55 ` Andrew Morton
2010-09-03 23:17 ` Christoph Lameter
2010-09-03 23:17 ` Christoph Lameter
2010-09-03 23:28 ` Andrew Morton
2010-09-03 23:28 ` Andrew Morton
2010-09-04 0:54 ` Christoph Lameter
2010-09-04 0:54 ` Christoph Lameter
2010-09-05 18:12 ` Mel Gorman
2010-09-05 18:12 ` Mel Gorman
2010-09-03 9:08 ` [PATCH 3/3] mm: page allocator: Drain per-cpu lists after direct reclaim allocation fails Mel Gorman
2010-09-03 9:08 ` Mel Gorman
2010-09-03 23:00 ` Andrew Morton
2010-09-03 23:00 ` Andrew Morton
2010-09-04 2:25 ` Dave Chinner
2010-09-04 2:25 ` Dave Chinner
2010-09-04 3:21 ` Andrew Morton
2010-09-04 3:21 ` Andrew Morton
2010-09-04 7:58 ` Dave Chinner
2010-09-04 7:58 ` Dave Chinner
2010-09-04 8:14 ` Dave Chinner
2010-09-04 8:14 ` Dave Chinner
[not found] ` <20100905015400.GA10714@localhost>
[not found] ` <20100905021555.GG705@dastard>
[not found] ` <20100905060539.GA17450@localhost>
[not found] ` <20100905131447.GJ705@dastard>
2010-09-05 13:45 ` Wu Fengguang
2010-09-05 13:45 ` Wu Fengguang
2010-09-05 23:33 ` Dave Chinner
2010-09-05 23:33 ` Dave Chinner
2010-09-06 4:02 ` Dave Chinner [this message]
2010-09-06 4:02 ` Dave Chinner
2010-09-06 8:40 ` Mel Gorman
2010-09-06 8:40 ` Mel Gorman
2010-09-06 21:50 ` Dave Chinner
2010-09-06 21:50 ` Dave Chinner
2010-09-08 8:49 ` Dave Chinner
2010-09-08 8:49 ` Dave Chinner
2010-09-09 12:39 ` Mel Gorman
2010-09-09 12:39 ` Mel Gorman
2010-09-10 6:17 ` Dave Chinner
2010-09-10 6:17 ` Dave Chinner
2010-09-07 14:23 ` Christoph Lameter
2010-09-07 14:23 ` Christoph Lameter
2010-09-08 2:13 ` Wu Fengguang
2010-09-08 2:13 ` Wu Fengguang
2010-09-04 3:23 ` Wu Fengguang
2010-09-04 3:23 ` Wu Fengguang
2010-09-04 3:59 ` Andrew Morton
2010-09-04 3:59 ` Andrew Morton
2010-09-04 4:37 ` Wu Fengguang
2010-09-04 4:37 ` Wu Fengguang
2010-09-05 18:22 ` Mel Gorman
2010-09-05 18:22 ` Mel Gorman
2010-09-05 18:14 ` Mel Gorman
2010-09-05 18:14 ` Mel Gorman
2010-09-08 7:43 ` KOSAKI Motohiro
2010-09-08 7:43 ` KOSAKI Motohiro
2010-09-08 20:05 ` Christoph Lameter
2010-09-08 20:05 ` Christoph Lameter
2010-09-09 12:41 ` Mel Gorman
2010-09-09 12:41 ` Mel Gorman
2010-09-09 13:45 ` Christoph Lameter
2010-09-09 13:45 ` Christoph Lameter
2010-09-09 13:55 ` Mel Gorman
2010-09-09 13:55 ` Mel Gorman
2010-09-09 14:32 ` Christoph Lameter
2010-09-09 14:32 ` Christoph Lameter
2010-09-09 15:05 ` Mel Gorman
2010-09-09 15:05 ` Mel Gorman
2010-09-10 2:56 ` KOSAKI Motohiro
2010-09-10 2:56 ` KOSAKI Motohiro
2010-09-03 23:05 ` [PATCH 0/3] Reduce watermark-related problems with the per-cpu allocator V4 Andrew Morton
2010-09-03 23:05 ` Andrew Morton
2010-09-21 11:17 ` Mel Gorman
2010-09-21 11:17 ` Mel Gorman
2010-09-21 12:58 ` [stable] " Greg KH
2010-09-21 12:58 ` Greg KH
2010-09-21 14:23 ` Mel Gorman
2010-09-21 14:23 ` Mel Gorman
2010-09-23 18:49 ` Greg KH
2010-09-23 18:49 ` Greg KH
2010-09-24 9:14 ` Mel Gorman
2010-09-24 9:14 ` Mel Gorman
-- strict thread matches above, loose matches on Subject: below --
2010-08-31 17:37 [PATCH 0/3] Reduce watermark-related problems with the per-cpu allocator V3 Mel Gorman
2010-08-31 17:37 ` [PATCH 3/3] mm: page allocator: Drain per-cpu lists after direct reclaim allocation fails Mel Gorman
2010-08-31 17:37 ` Mel Gorman
2010-08-31 18:26 ` Christoph Lameter
2010-08-31 18:26 ` Christoph Lameter
2010-08-23 8:00 [PATCH 0/3] Reduce watermark-related problems with the per-cpu allocator V2 Mel Gorman
2010-08-23 8:00 ` [PATCH 3/3] mm: page allocator: Drain per-cpu lists after direct reclaim allocation fails Mel Gorman
2010-08-23 8:00 ` Mel Gorman
2010-08-23 23:17 ` KOSAKI Motohiro
2010-08-23 23:17 ` KOSAKI Motohiro
2010-08-16 9:42 [RFC PATCH 0/3] Reduce watermark-related problems with the per-cpu allocator Mel Gorman
2010-08-16 9:42 ` [PATCH 3/3] mm: page allocator: Drain per-cpu lists after direct reclaim allocation fails Mel Gorman
2010-08-16 14:50 ` Rik van Riel
2010-08-17 2:57 ` Minchan Kim
2010-08-18 3:02 ` KAMEZAWA Hiroyuki
2010-08-19 14:47 ` Minchan Kim
2010-08-19 15:10 ` Mel Gorman
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20100906040243.GA7362@dastard \
--to=david@fromorbit.com \
--cc=akpm@linux-foundation.org \
--cc=cl@linux-foundation.org \
--cc=fengguang.wu@intel.com \
--cc=hannes@cmpxchg.org \
--cc=kamezawa.hiroyu@jp.fujitsu.com \
--cc=kosaki.motohiro@jp.fujitsu.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-mm@kvack.org \
--cc=mel@csn.ul.ie \
--cc=minchan.kim@gmail.com \
--cc=riel@redhat.com \
--cc=rientjes@google.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.