2016-10-04 17:10:00

by Dave Jones

[permalink] [raw]
Subject: page_cache_tree_insert WARN_ON hit on 4.8+

Hit this during a trinity run.
Kernel built from v4.8-1558-g21f54ddae449

WARNING: CPU: 0 PID: 5670 at ./include/linux/swap.h:276 page_cache_tree_insert+0x198/0x1b0
CPU: 0 PID: 5670 Comm: trinity-c6 Not tainted 4.8.0-think+ #2
ffffc900003a3ab8 ffffffffb03dc311 0000000000000000 0000000000000000
ffffffffb0c063d6 ffffffffb018d898 ffffc900003a3af8 ffffffffb008b550
00000114003a3b30 ffffffffb0c063d6 0000000000000114 0000000000000000
Call Trace:
[<ffffffffb03dc311>] dump_stack+0x6c/0x9b
[<ffffffffb018d898>] ? page_cache_tree_insert+0x198/0x1b0
[<ffffffffb008b550>] __warn+0x110/0x130
[<ffffffffb008b6dc>] warn_slowpath_null+0x2c/0x40
[<ffffffffb018d898>] page_cache_tree_insert+0x198/0x1b0
[<ffffffffb01900c4>] __add_to_page_cache_locked+0x1a4/0x3a0
[<ffffffffb0190379>] add_to_page_cache_lru+0x79/0x1c0
[<ffffffffb0193456>] generic_file_read_iter+0x916/0xce0
[<ffffffffb0232090>] do_iter_readv_writev+0x120/0x1c0
[<ffffffffb0192b40>] ? wait_on_page_bit_killable+0x100/0x100
[<ffffffffb0192b40>] ? wait_on_page_bit_killable+0x100/0x100
[<ffffffffb0232e29>] do_readv_writev+0x1f9/0x2e0
[<ffffffffb025d44e>] ? __fdget_pos+0x5e/0x70
[<ffffffffb025d44e>] ? __fdget_pos+0x5e/0x70
[<ffffffffb025d44e>] ? __fdget_pos+0x5e/0x70
[<ffffffffb0232f74>] vfs_readv+0x64/0x90
[<ffffffffb023300d>] do_readv+0x6d/0x120
[<ffffffffb0234907>] SyS_readv+0x27/0x30
[<ffffffffb000276f>] do_syscall_64+0x7f/0x200
[<ffffffffb09cfa8b>] entry_SYSCALL64_slow_path+0x25/0x25



2016-10-04 17:34:29

by Johannes Weiner

[permalink] [raw]
Subject: Re: page_cache_tree_insert WARN_ON hit on 4.8+

Hi Dave,

On Tue, Oct 04, 2016 at 01:09:55PM -0400, Dave Jones wrote:
> Hit this during a trinity run.
> Kernel built from v4.8-1558-g21f54ddae449
>
> WARNING: CPU: 0 PID: 5670 at ./include/linux/swap.h:276 page_cache_tree_insert+0x198/0x1b0
> CPU: 0 PID: 5670 Comm: trinity-c6 Not tainted 4.8.0-think+ #2
> ffffc900003a3ab8 ffffffffb03dc311 0000000000000000 0000000000000000
> ffffffffb0c063d6 ffffffffb018d898 ffffc900003a3af8 ffffffffb008b550
> 00000114003a3b30 ffffffffb0c063d6 0000000000000114 0000000000000000
> Call Trace:
> [<ffffffffb03dc311>] dump_stack+0x6c/0x9b
> [<ffffffffb018d898>] ? page_cache_tree_insert+0x198/0x1b0
> [<ffffffffb008b550>] __warn+0x110/0x130
> [<ffffffffb008b6dc>] warn_slowpath_null+0x2c/0x40
> [<ffffffffb018d898>] page_cache_tree_insert+0x198/0x1b0
> [<ffffffffb01900c4>] __add_to_page_cache_locked+0x1a4/0x3a0
> [<ffffffffb0190379>] add_to_page_cache_lru+0x79/0x1c0
> [<ffffffffb0193456>] generic_file_read_iter+0x916/0xce0
> [<ffffffffb0232090>] do_iter_readv_writev+0x120/0x1c0
> [<ffffffffb0192b40>] ? wait_on_page_bit_killable+0x100/0x100
> [<ffffffffb0192b40>] ? wait_on_page_bit_killable+0x100/0x100
> [<ffffffffb0232e29>] do_readv_writev+0x1f9/0x2e0
> [<ffffffffb025d44e>] ? __fdget_pos+0x5e/0x70
> [<ffffffffb025d44e>] ? __fdget_pos+0x5e/0x70
> [<ffffffffb025d44e>] ? __fdget_pos+0x5e/0x70
> [<ffffffffb0232f74>] vfs_readv+0x64/0x90
> [<ffffffffb023300d>] do_readv+0x6d/0x120
> [<ffffffffb0234907>] SyS_readv+0x27/0x30
> [<ffffffffb000276f>] do_syscall_64+0x7f/0x200
> [<ffffffffb09cfa8b>] entry_SYSCALL64_slow_path+0x25/0x25

Thanks for the report.

I've been trying to reproduce this too after Linus got hit by it. Is
there any way to trace back the steps what trinity was doing exactly?
What kind of file(system) this was operating on, file size, what the
/proc/vmstat delta before the operation until the trigger looks like?

The call to WARN() is new, the actual underlying bug could have been
around for a while, making it hard to narrow down.

2016-10-04 17:46:50

by Dave Jones

[permalink] [raw]
Subject: Re: page_cache_tree_insert WARN_ON hit on 4.8+

On Tue, Oct 04, 2016 at 07:34:25PM +0200, Johannes Weiner wrote:
> Hi Dave,
>
> On Tue, Oct 04, 2016 at 01:09:55PM -0400, Dave Jones wrote:
> > Hit this during a trinity run.
> > Kernel built from v4.8-1558-g21f54ddae449
> >
> > WARNING: CPU: 0 PID: 5670 at ./include/linux/swap.h:276 page_cache_tree_insert+0x198/0x1b0
>
> Thanks for the report.
>
> I've been trying to reproduce this too after Linus got hit by it. Is
> there any way to trace back the steps what trinity was doing exactly?

That run didn't have logging enabled, so not sure..

> What kind of file(system) this was operating on,

btrfs

> file size, what the /proc/vmstat delta before the operation until the trigger looks like?

No idea.

Let me play with some options, see if I can narrow it down.

Dave

2016-10-06 13:42:02

by Johannes Weiner

[permalink] [raw]
Subject: Re: page_cache_tree_insert WARN_ON hit on 4.8+

On Tue, Oct 04, 2016 at 01:46:45PM -0400, Dave Jones wrote:
> On Tue, Oct 04, 2016 at 07:34:25PM +0200, Johannes Weiner wrote:
> > On Tue, Oct 04, 2016 at 01:09:55PM -0400, Dave Jones wrote:
> > > Hit this during a trinity run.
> > > Kernel built from v4.8-1558-g21f54ddae449
> > >
> > > WARNING: CPU: 0 PID: 5670 at ./include/linux/swap.h:276 page_cache_tree_insert+0x198/0x1b0

To tie up this thread, we tracked it down in another thread and Linus
merged a fix for this:

https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=d3798ae8c6f3767c726403c2ca6ecc317752c9dd

2016-10-06 14:02:29

by Dave Jones

[permalink] [raw]
Subject: Re: page_cache_tree_insert WARN_ON hit on 4.8+

On Thu, Oct 06, 2016 at 03:41:45PM +0200, Johannes Weiner wrote:
> On Tue, Oct 04, 2016 at 01:46:45PM -0400, Dave Jones wrote:
> > On Tue, Oct 04, 2016 at 07:34:25PM +0200, Johannes Weiner wrote:
> > > On Tue, Oct 04, 2016 at 01:09:55PM -0400, Dave Jones wrote:
> > > > Hit this during a trinity run.
> > > > Kernel built from v4.8-1558-g21f54ddae449
> > > >
> > > > WARNING: CPU: 0 PID: 5670 at ./include/linux/swap.h:276 page_cache_tree_insert+0x198/0x1b0
>
> To tie up this thread, we tracked it down in another thread and Linus
> merged a fix for this:
>
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=d3798ae8c6f3767c726403c2ca6ecc317752c9dd

Yep, can confirm I've seen no reoccurrences since that merge.

Dave