Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1475220 > unrolled thread

Re: [writeback] 8bc4ad9498: INFO: suspicious RCU usage. ]

Started byTejun Heo <tj@kernel.org>
First post2016-09-02 17:00 +0200
Last post2016-09-02 20:10 +0200
Articles 4 — 2 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [writeback] 8bc4ad9498: INFO: suspicious RCU usage. ] Tejun Heo <tj@kernel.org> - 2016-09-02 17:00 +0200
    Re: [writeback] 8bc4ad9498: INFO: suspicious RCU usage. ] "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-09-02 17:40 +0200
      Re: [writeback] 8bc4ad9498: INFO: suspicious RCU usage. ] "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-09-02 19:50 +0200
        Re: [writeback] 8bc4ad9498: INFO: suspicious RCU usage. ] Tejun Heo <tj@kernel.org> - 2016-09-02 20:10 +0200

#1475220 — Re: [writeback] 8bc4ad9498: INFO: suspicious RCU usage. ]

FromTejun Heo <tj@kernel.org>
Date2016-09-02 17:00 +0200
SubjectRe: [writeback] 8bc4ad9498: INFO: suspicious RCU usage. ]
Message-ID<scY6K-KW-9@gated-at.bofh.it>
(cc'ing Paul, hi!)

Hello,

On Thu, Sep 01, 2016 at 02:13:34PM -0600, Jens Axboe wrote:
> On 09/01/2016 04:21 AM, kernel test robot wrote:
> > [    7.323356] cdrom: Uniform CD-ROM driver Revision: 3.20
> > [    7.334239]
> > [    7.337256] ===============================
> > [    7.340532] [ INFO: suspicious RCU usage. ]
> > [    7.342419] 4.8.0-rc4-00008-g8bc4ad9 #1 Not tainted
> > [    7.347065] -------------------------------
> > [    7.350132] include/linux/cgroup.h:435 suspicious rcu_dereference_check() usage!
...
> > [    7.410074] Call Trace:
> > [    7.411328]  [<ffffffff8178ed3b>] dump_stack+0x82/0xb8
> > [    7.413982]  [<ffffffff81123472>] lockdep_rcu_suspicious+0xf7/0x100
> > [    7.415828]  [<ffffffff817873f4>] bio_blkcg+0x89/0x93
> > [    7.417336]  [<ffffffff817891f0>] check_blkcg_changed+0x58/0x1b8
> > [    7.428722]  [<ffffffff81789b90>] cfq_set_request+0xd1/0x2a3
> > [    7.439690]  [<ffffffff81763fe3>] elv_set_request+0x1f/0x24
> > [    7.442157]  [<ffffffff8176856d>] get_request+0x38f/0x77f
> > [    7.447449]  [<ffffffff817689c2>] blk_get_request+0x65/0xa8
> > [    7.449868]  [<ffffffff81c692df>] ide_cd_queue_pc+0x76/0x19d
> > [    7.453757]  [<ffffffff81c695ee>] cdrom_check_status+0x51/0x53
> > [    7.455372]  [<ffffffff81c6a27e>] ide_cdrom_check_events_real+0x20/0x3f
> > [    7.457294]  [<ffffffff82579f94>] cdrom_update_events+0x18/0x21
> > [    7.458987]  [<ffffffff82579faf>] cdrom_check_events+0x12/0x1f
> > [    7.460713]  [<ffffffff81c68317>] idecd_check_events+0x1c/0x1e
> > [    7.462393]  [<ffffffff81778d12>] disk_check_events+0x47/0x103
> > [    7.464129]  [<ffffffff81778dea>] disk_events_workfn+0x1c/0x1e
> > [    7.465844]  [<ffffffff810fcafa>] process_one_work+0x272/0x4ee
> > [    7.467462]  [<ffffffff810fd247>] worker_thread+0x1eb/0x2c9

The warning is from

#define task_css_set_check(task, __c)					\
	rcu_dereference_check((task)->cgroups,				\
		lockdep_is_held(&cgroup_mutex) ||			\
		lockdep_is_held(&css_set_lock) ||			\
		((task)->flags & PF_EXITING) || (__c))

which is used by bio_blkcg() which is called by the following code in
check_blkcg_changed().

	rcu_read_lock();
	serial_nr = bio_blkcg(bio)->css.serial_nr;
	rcu_read_unlock();

So, I have no idea.  It looks like rcu_dereference_check() is being
called with rcu read locked but still triggering suspicious RCU usage
warning.

The code hasn't changed for quite a while now, so it's also really
weird that it's triggering now.  Paul, does anything ring a bell?

Thanks.

-- 
tejun

[toc] | [next] | [standalone]

#1475254

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-09-02 17:40 +0200
Message-ID<scYJs-1dc-27@gated-at.bofh.it>
In reply to#1475220
On Fri, Sep 02, 2016 at 10:56:22AM -0400, Tejun Heo wrote:
> (cc'ing Paul, hi!)
> 
> Hello,
> 
> On Thu, Sep 01, 2016 at 02:13:34PM -0600, Jens Axboe wrote:
> > On 09/01/2016 04:21 AM, kernel test robot wrote:
> > > [    7.323356] cdrom: Uniform CD-ROM driver Revision: 3.20
> > > [    7.334239]
> > > [    7.337256] ===============================
> > > [    7.340532] [ INFO: suspicious RCU usage. ]
> > > [    7.342419] 4.8.0-rc4-00008-g8bc4ad9 #1 Not tainted
> > > [    7.347065] -------------------------------
> > > [    7.350132] include/linux/cgroup.h:435 suspicious rcu_dereference_check() usage!

Lockdep does not believe that any locks are held, correct?

> ...
> > > [    7.410074] Call Trace:
> > > [    7.411328]  [<ffffffff8178ed3b>] dump_stack+0x82/0xb8
> > > [    7.413982]  [<ffffffff81123472>] lockdep_rcu_suspicious+0xf7/0x100
> > > [    7.415828]  [<ffffffff817873f4>] bio_blkcg+0x89/0x93
> > > [    7.417336]  [<ffffffff817891f0>] check_blkcg_changed+0x58/0x1b8
> > > [    7.428722]  [<ffffffff81789b90>] cfq_set_request+0xd1/0x2a3
> > > [    7.439690]  [<ffffffff81763fe3>] elv_set_request+0x1f/0x24
> > > [    7.442157]  [<ffffffff8176856d>] get_request+0x38f/0x77f
> > > [    7.447449]  [<ffffffff817689c2>] blk_get_request+0x65/0xa8
> > > [    7.449868]  [<ffffffff81c692df>] ide_cd_queue_pc+0x76/0x19d
> > > [    7.453757]  [<ffffffff81c695ee>] cdrom_check_status+0x51/0x53
> > > [    7.455372]  [<ffffffff81c6a27e>] ide_cdrom_check_events_real+0x20/0x3f
> > > [    7.457294]  [<ffffffff82579f94>] cdrom_update_events+0x18/0x21
> > > [    7.458987]  [<ffffffff82579faf>] cdrom_check_events+0x12/0x1f
> > > [    7.460713]  [<ffffffff81c68317>] idecd_check_events+0x1c/0x1e
> > > [    7.462393]  [<ffffffff81778d12>] disk_check_events+0x47/0x103
> > > [    7.464129]  [<ffffffff81778dea>] disk_events_workfn+0x1c/0x1e
> > > [    7.465844]  [<ffffffff810fcafa>] process_one_work+0x272/0x4ee
> > > [    7.467462]  [<ffffffff810fd247>] worker_thread+0x1eb/0x2c9
> 
> The warning is from
> 
> #define task_css_set_check(task, __c)					\
> 	rcu_dereference_check((task)->cgroups,				\
> 		lockdep_is_held(&cgroup_mutex) ||			\
> 		lockdep_is_held(&css_set_lock) ||			\
> 		((task)->flags & PF_EXITING) || (__c))
> 
> which is used by bio_blkcg() which is called by the following code in
> check_blkcg_changed().
> 
> 	rcu_read_lock();
> 	serial_nr = bio_blkcg(bio)->css.serial_nr;
> 	rcu_read_unlock();
> 
> So, I have no idea.  It looks like rcu_dereference_check() is being
> called with rcu read locked but still triggering suspicious RCU usage
> warning.

Perhaps there is an rcu_read_unlock() somewhere on the code path?

> The code hasn't changed for quite a while now, so it's also really
> weird that it's triggering now.  Paul, does anything ring a bell?

I have not see something like this recently.

							Thanx, Paul

[toc] | [prev] | [next] | [standalone]

#1475375

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-09-02 19:50 +0200
Message-ID<sd0Lg-2s9-7@gated-at.bofh.it>
In reply to#1475254
On Fri, Sep 02, 2016 at 09:49:25AM -0600, Jens Axboe wrote:
> On 09/02/2016 09:36 AM, Paul E. McKenney wrote:
> >On Fri, Sep 02, 2016 at 10:56:22AM -0400, Tejun Heo wrote:
> >>(cc'ing Paul, hi!)
> >>
> >>Hello,
> >>
> >>On Thu, Sep 01, 2016 at 02:13:34PM -0600, Jens Axboe wrote:
> >>>On 09/01/2016 04:21 AM, kernel test robot wrote:
> >>>>[    7.323356] cdrom: Uniform CD-ROM driver Revision: 3.20
> >>>>[    7.334239]
> >>>>[    7.337256] ===============================
> >>>>[    7.340532] [ INFO: suspicious RCU usage. ]
> >>>>[    7.342419] 4.8.0-rc4-00008-g8bc4ad9 #1 Not tainted
> >>>>[    7.347065] -------------------------------
> >>>>[    7.350132] include/linux/cgroup.h:435 suspicious rcu_dereference_check() usage!
> >
> >Lockdep does not believe that any locks are held, correct?
> 
> Which is correct, the queue lock has been dropped at this point.

Note that lockdep believes that the rcu_read_lock() has also been
dropped, otherwise it would have listed it.

> >>>>[    7.410074] Call Trace:
> >>>>[    7.411328]  [<ffffffff8178ed3b>] dump_stack+0x82/0xb8
> >>>>[    7.413982]  [<ffffffff81123472>] lockdep_rcu_suspicious+0xf7/0x100
> >>>>[    7.415828]  [<ffffffff817873f4>] bio_blkcg+0x89/0x93
> >>>>[    7.417336]  [<ffffffff817891f0>] check_blkcg_changed+0x58/0x1b8
> >>>>[    7.428722]  [<ffffffff81789b90>] cfq_set_request+0xd1/0x2a3
> >>>>[    7.439690]  [<ffffffff81763fe3>] elv_set_request+0x1f/0x24
> >>>>[    7.442157]  [<ffffffff8176856d>] get_request+0x38f/0x77f
> >>>>[    7.447449]  [<ffffffff817689c2>] blk_get_request+0x65/0xa8
> >>>>[    7.449868]  [<ffffffff81c692df>] ide_cd_queue_pc+0x76/0x19d
> >>>>[    7.453757]  [<ffffffff81c695ee>] cdrom_check_status+0x51/0x53
> >>>>[    7.455372]  [<ffffffff81c6a27e>] ide_cdrom_check_events_real+0x20/0x3f
> >>>>[    7.457294]  [<ffffffff82579f94>] cdrom_update_events+0x18/0x21
> >>>>[    7.458987]  [<ffffffff82579faf>] cdrom_check_events+0x12/0x1f
> >>>>[    7.460713]  [<ffffffff81c68317>] idecd_check_events+0x1c/0x1e
> >>>>[    7.462393]  [<ffffffff81778d12>] disk_check_events+0x47/0x103
> >>>>[    7.464129]  [<ffffffff81778dea>] disk_events_workfn+0x1c/0x1e
> >>>>[    7.465844]  [<ffffffff810fcafa>] process_one_work+0x272/0x4ee
> >>>>[    7.467462]  [<ffffffff810fd247>] worker_thread+0x1eb/0x2c9
> >>
> >>The warning is from
> >>
> >>#define task_css_set_check(task, __c)					\
> >>	rcu_dereference_check((task)->cgroups,				\
> >>		lockdep_is_held(&cgroup_mutex) ||			\
> >>		lockdep_is_held(&css_set_lock) ||			\
> >>		((task)->flags & PF_EXITING) || (__c))
> >>
> >>which is used by bio_blkcg() which is called by the following code in
> >>check_blkcg_changed().
> >>
> >>	rcu_read_lock();
> >>	serial_nr = bio_blkcg(bio)->css.serial_nr;
> >>	rcu_read_unlock();
> >>
> >>So, I have no idea.  It looks like rcu_dereference_check() is being
> >>called with rcu read locked but still triggering suspicious RCU usage
> >>warning.
> >
> >Perhaps there is an rcu_read_unlock() somewhere on the code path?
> >
> >>The code hasn't changed for quite a while now, so it's also really
> >>weird that it's triggering now.  Paul, does anything ring a bell?
> >
> >I have not see something like this recently.
> 
> The question is if it's really new, or just re-triggering because the
> writeback branch changes that function? It's further down though, so
> can't impact the RCU section. And the writeback changes don't have any
> RCU code in them...

At this point, I have to suggest "git bisect"...

							Thanx, Paul

[toc] | [prev] | [next] | [standalone]

#1475382

FromTejun Heo <tj@kernel.org>
Date2016-09-02 20:10 +0200
Message-ID<sd14C-2Oa-21@gated-at.bofh.it>
In reply to#1475375
Hello, Paul.

On Fri, Sep 02, 2016 at 10:00:56AM -0700, Paul E. McKenney wrote:
> Note that lockdep believes that the rcu_read_lock() has also been
> dropped, otherwise it would have listed it.

There isn't any actual code between rcu_read_lock() and the following
rcu deref.  That's the first thing which happens.  It looked
mysterious to me so I was wondering whether you knew any brekages on
rcu lockdep side.  Unfortunately, that doesn't seem to be the case.

> At this point, I have to suggest "git bisect"...

I'll try to reproduce it and see wth is going on.

Thanks!

-- 
tejun

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web