linux-kernel - Re: [gcov_enable_events] WARNING: bad unlock balance detected!

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Date:   Tue, 7 Nov 2017 20:29:11 +0800
From:   Fengguang Wu <fengguang.wu@...el.com>
To:     linux-kernel@...r.kernel.org
Cc:     Linus Torvalds <torvalds@...ux-foundation.org>,
        Frantisek Hrbata <fhrbata@...hat.com>,
        Peter Oberparleiter <oberpar@...ux.vnet.ibm.com>,
        Masahiro Yamada <yamada.m@...panasonic.com>,
        Peter Zijlstra <peterz@...radead.org>
Subject: Re: [gcov_enable_events] WARNING: bad unlock balance detected!

Sorry please ignore this report -- according to Peter:

This is fixed by commit:

  02a7c234e540 ("rcu: Suppress lockdep false-positive ->boost_mtx complaints")

The problem is that RCU boosting was mixing futex and !futex rt_mutex
ops.
On Tue, Nov 07, 2017 at 09:52:09AM +0800, Fengguang Wu wrote:
>Hi,
>
>Here is a warning in v4.14-rc8 -- it's not necessarily a new bug.
>
>[   29.314270] rcu-perf: rcu_perf_writer task started
>[   29.329146] audit: initializing netlink subsys (disabled)
>[   29.337989] audit: type=2000 audit(1510004207.289:1): state=initialized audit_enabled=0 res=1
>[   39.708008]
>[   39.710234] =====================================
>[   39.710234] WARNING: bad unlock balance detected!
>[   39.710234] 4.14.0-rc8 #1 Not tainted
>[   39.710234] -------------------------------------
>[   39.710234] swapper/0/1 is trying to release lock (rcu_preempt_state) at:
>[   39.710234] [<cb4992e3>] rcu_read_unlock_special+0x6e3/0x800
>[   39.710234] but there are no more locks to release!
>[   39.710234]
>[   39.710234] other info that might help us debug this:
>[   39.710234] 4 locks held by swapper/0/1:
>[   39.710234]  #0:  (gcov_lock){+.+.}, at: [<cb5176b3>] gcov_enable_events+0x23/0xc0
>[   39.710234]  #1:  (node_lock){+.+.}, at: [<cb518cef>] gcov_event+0x2f/0x7a0
>[   39.710234]  #2:  (&sb->s_type->i_mutex_key#3){+.+.}, at: [<cb7d645d>] start_creating+0xcd/0x240
>[   39.710234]  #3:  (rcu_read_lock){....}, at: [<cb6e3b20>] __d_lookup+0x0/0x520
>[   39.710234]
>[   39.710234] stack backtrace:
>[   39.710234] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.14.0-rc8 #1
>[   39.710234] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>[   39.710234] Call Trace:
>[   39.710234]  dump_stack+0x146/0x1e6
>[   39.710234]  ? rcu_read_unlock_special+0x6e3/0x800
>[   39.710234]  print_unlock_imbalance_bug+0x1cc/0x1f0
>[   39.710234]  ? rcu_read_unlock_special+0x6e3/0x800
>[   39.710234]  lock_release+0x41b/0xa90
>[   39.710234]  ? mark_held_locks+0xd7/0x120
>[   39.710234]  ? rcu_read_unlock_special+0x6e3/0x800
>[   39.710234]  rt_mutex_unlock+0x3f/0x170
>[   39.710234]  ? _raw_spin_unlock_irqrestore+0x133/0x170
>[   39.710234]  rcu_read_unlock_special+0x6e3/0x800
>[   39.710234]  ? __lock_is_held+0x58/0xe0
>[   39.710234]  __rcu_read_unlock+0xbc/0x180
>[   39.710234]  __d_lookup+0x4de/0x520
>[   39.710234]  ? __d_lookup_rcu+0x420/0x420
>[   39.710234]  ? d_lookup+0x11b/0x240
>[   39.710234]  ? trace_hardirqs_on_caller+0x2d2/0x430
>[   39.710234]  d_lookup+0x1b7/0x240
>[   39.710234]  ? lookup_dcache+0x2f/0x170
>[   39.710234]  lookup_dcache+0x2f/0x170
>[   39.710234]  __lookup_hash+0x2e/0x1c0
>[   39.710234]  lookup_one_len+0x282/0x2a0
>[   39.710234]  start_creating+0xfb/0x240
>[   39.710234]  __debugfs_create_file+0xc7/0x2f0
>[   39.710234]  debugfs_create_file+0x50/0x70
>[   39.710234]  new_node+0x1b5/0x350
>[   39.710234]  gcov_event+0x344/0x7a0
>[   39.710234]  ? gcov_persist_setup+0x90/0x90
>[   39.710234]  gcov_enable_events+0x57/0xc0
>[   39.710234]  gcov_fs_init+0xf3/0x13d
>[   39.710234]  do_one_initcall+0x113/0x2b1
>[   39.710234]  ? kernel_init_freeable+0x236/0x3b4
>[   39.710234]  kernel_init_freeable+0x260/0x3b4
>[   39.710234]  ? rest_init+0x440/0x440
>[   39.710234]  kernel_init+0x1e/0x290
>[   39.710234]  ? schedule_tail_wrapper+0x9/0xc
>[   39.710234]  ret_from_fork+0x19/0x24
>[   40.559851] rcu-perf: rcu_perf_writer 1 has 100 measurements
>[   40.567049] rcu-perf: rcu_perf_writer 0 has 100 measurements
>[   40.617286] Dumping ftrace buffer:
>[   40.620255]    (ftrace buffer empty)
>[   40.628854] rcu-perf: Test complete
>
>Thanks,
>Fengguang