Re: [RFC RT v5.10] [rt] repair usage of dev_base_lock in netstat_show()

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On Mon, Oct 18, 2021 at 12:42 PM Luis Goncalves <lgoncalv@xxxxxxxxxx> wrote:
>
> On Mon, Oct 11, 2021 at 1:36 PM Sebastian Andrzej Siewior
> <bigeasy@xxxxxxxxxxxxx> wrote:
> >
> > On 2021-10-11 15:56:09 [+0200], To Luis Claudio R. Goncalves wrote:
> > > So my guess is that the _bh isn't needed.
> >
> > Correction: If there is at least _one_ reader in softirq all, writer
> > need to disable BH which _might_ be the case here.
> > The splat is probably because on read_lock holder disables BH later on
> > which I don't see yet.
> >
> > Sebastian
>
> The way I was able to reproduce the problem in 5.10 (and in 5.14 before -rt11)
> was:
>
>     1. systemctl disable tuned.service
>     2. Reboot to a kernel-rt with lockdep support
>     3. systemctl start tuned.service
>
> I used a few tuned profiles, but stuck with 'realtime' for obvious reasons.
>
> If that helps in the process I can investigate which specific
> action/configuration
> performed by tuned is triggering the lockdep splat.

Just for the sake of completeness, this is the lockdep splat for v5.10.73-rt54:

[   41.917124] hrtimer: interrupt took 19800197 ns
[   45.105231] bnxt_en 0000:19:00.0 eno1np0: NIC Link is Up, 10000
Mbps full duplex, Flow control: ON - receive & transmit
[   45.105235] bnxt_en 0000:19:00.0 eno1np0: FEC autoneg off encoding: None

[   46.370088] ======================================================
[   46.370089] WARNING: possible circular locking dependency detected
[   46.370089] 5.10.73-rt54.lockdep+ #2 Tainted: G          I
[   46.370091] ------------------------------------------------------
[   46.370091] tuned/2248 is trying to acquire lock:
[   46.370093] ffff954d9e818220
((softirq_ctrl.lock).lock){+.+.}-{2:2}, at:
__local_bh_disable_ip+0x116/0x2f0
[   46.370104]
               but task is already holding lock:
[   46.370104] ffffffff9ccafa60 (dev_base_lock){++.+}-{0:0}, at:
netstat_show.isra.17+0x4a/0xb0
[   46.370111]
               which lock already depends on the new lock.

[   46.370111]
               the existing dependency chain (in reverse order) is:
[   46.370111]
               -> #1 (dev_base_lock){++.+}-{0:0}:
[   46.370113]        lock_acquire+0xde/0x380
[   46.370117]        rt_write_lock+0x3a/0x1b0
[   46.370122]        list_netdevice+0x4c/0x140
[   46.370125]        register_netdevice+0x59b/0x810
[   46.370127]        register_netdev+0x1a/0x30
[   46.370128]        loopback_net_init+0x48/0xa0
[   46.370130]        ops_init+0x3a/0x180
[   46.370133]        register_pernet_operations+0x126/0x220
[   46.370135]        register_pernet_device+0x25/0x60
[   46.370138]        net_dev_init+0x31b/0x391
[   46.370141]        do_one_initcall+0x74/0x440
[   46.370145]        kernel_init_freeable+0x39d/0x408
[   46.370148]        kernel_init+0xb/0x12e
[   46.370150]        ret_from_fork+0x1f/0x30
[   46.370152]
               -> #0 ((softirq_ctrl.lock).lock){+.+.}-{2:2}:
[   46.370153]        check_prevs_add+0x1bb/0xe50
[   46.370155]        __lock_acquire+0x1187/0x1640
[   46.370157]        lock_acquire+0xde/0x380
[   46.370158]        rt_spin_lock+0x2b/0xd0
[   46.370160]        __local_bh_disable_ip+0x116/0x2f0
[   46.370162]        tg3_get_stats64+0x29/0xb0 [tg3]
[   46.370167]        dev_get_stats+0x5b/0xc0
[   46.370168]        netstat_show.isra.17+0x5b/0xb0
[   46.370170]        dev_attr_show+0x18/0x50
[   46.370173]        sysfs_kf_seq_show+0xa1/0x130
[   46.370176]        seq_read_iter+0x19e/0x420
[   46.370178]        new_sync_read+0x121/0x1c0
[   46.370180]        vfs_read+0x185/0x1e0
[   46.370182]        ksys_read+0x5f/0xe0
[   46.370184]        do_syscall_64+0x33/0x40
[   46.370186]        entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   46.370188]
               other info that might help us debug this:

[   46.370188]  Possible unsafe locking scenario:

[   46.370189]        CPU0                    CPU1
[   46.370189]        ----                    ----
[   46.370189]   lock(dev_base_lock);
[   46.370190]                                lock((softirq_ctrl.lock).lock);
[   46.370191]                                lock(dev_base_lock);
[   46.370192]   lock((softirq_ctrl.lock).lock);
[   46.370193]
                *** DEADLOCK ***

[   46.370193] 6 locks held by tuned/2248:
[   46.370194]  #0: ffff954606ef7d30 (&f->f_pos_lock){+.+.}-{0:0}, at:
__fdget_pos+0x4b/0x60
[   46.370199]  #1: ffff9545d307a1f0 (&p->lock){+.+.}-{0:0}, at:
seq_read_iter+0x56/0x420
[   46.370202]  #2: ffff9545fcde6cb8 (&of->mutex){+.+.}-{0:0}, at:
kernfs_seq_start+0x28/0x90
[   46.370205]  #3: ffff953e5c12dd98 (kn->active#246){.+.+}-{0:0}, at:
kernfs_seq_start+0x30/0x90
[   46.370208]  #4: ffffffff9ccafa60 (dev_base_lock){++.+}-{0:0}, at:
netstat_show.isra.17+0x4a/0xb0
[   46.370211]  #5: ffffffff9c8c8fe0 (rcu_read_lock){....}-{1:2}, at:
rt_read_lock+0x7d/0x1e0
[   46.370214]
               stack backtrace:
[   46.370214] CPU: 27 PID: 2248 Comm: tuned Tainted: G          I
  5.10.73-rt54.lockdep+ #2
[   46.370216] Hardware name: Dell Inc. PowerEdge R740/07X9K0, BIOS
2.8.2 08/27/2020
[   46.370217] Call Trace:
[   46.370218]  dump_stack+0x77/0x97
[   46.370224]  check_noncircular+0xff/0x120
[   46.370228]  check_prevs_add+0x1bb/0xe50
[   46.370232]  __lock_acquire+0x1187/0x1640
[   46.370236]  lock_acquire+0xde/0x380
[   46.370237]  ? __local_bh_disable_ip+0x116/0x2f0
[   46.370242]  ? tg3_get_stats64+0x5/0xb0 [tg3]
[   46.370245]  rt_spin_lock+0x2b/0xd0
[   46.370246]  ? __local_bh_disable_ip+0x116/0x2f0
[   46.370249]  __local_bh_disable_ip+0x116/0x2f0
[   46.370251]  tg3_get_stats64+0x29/0xb0 [tg3]
[   46.370255]  dev_get_stats+0x5b/0xc0
[   46.370257]  netstat_show.isra.17+0x5b/0xb0
[   46.370263]  dev_attr_show+0x18/0x50
[   46.370264]  sysfs_kf_seq_show+0xa1/0x130
[   46.370266]  seq_read_iter+0x19e/0x420
[   46.370269]  new_sync_read+0x121/0x1c0
[   46.370272]  vfs_read+0x185/0x1e0
[   46.370274]  ksys_read+0x5f/0xe0
[   46.370276]  do_syscall_64+0x33/0x40
[   46.370278]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   46.370280] RIP: 0033:0x7f4ee932b9e4
[   46.370282] Code: c3 0f 1f 44 00 00 41 54 49 89 d4 55 48 89 f5 53
89 fb 48 83 ec 10 e8 7b fc ff ff 4c 89 e2 48 89 ee 89 df 41 89 c0 31
c0 0f 05 <48> 3d 00 f0 ff ff 77 38 44 89 c7 48 89 44 24 08 e8 b7 fc ff
ff 48
[   46.370283] RSP: 002b:00007f4ede603be0 EFLAGS: 00000246 ORIG_RAX:
0000000000000000
[   46.370285] RAX: ffffffffffffffda RBX: 0000000000000039 RCX: 00007f4ee932b9e4
[   46.370286] RDX: 0000000000001001 RSI: 00007f4ed801b670 RDI: 0000000000000039
[   46.370287] RBP: 00007f4ed801b670 R08: 0000000000000000 R09: 0000000000000003
[   46.370288] R10: 0000000000000001 R11: 0000000000000246 R12: 0000000000001001
[   46.370289] R13: 0000000000000039 R14: 00007f4ed801b670 R15: 000055cd6476e060
[   47.606432] DMA-API: dma_debug_entry pool grown to 131072 (200%)
[   49.474083] DMA-API: dma_debug_entry pool grown to 196608 (300%)
[   49.653708] DMA-API: dma_debug_entry pool grown to 262144 (400%)

Luis




[Index of Archives]     [Linux USB Development]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]

  Powered by Linux