CONFIG_SHUFFLE_PAGE_ALLOCATOR=y lockdep splat (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang)

[Qian Cai <cai@lca.pw>]

Adjusted Cc a bit as this looks like more of the scheduler territory.

> On Sep 10, 2019, at 3:49 PM, Qian Cai <cai@lca.pw> wrote:
> 
> Hmm, it feels like that CONFIG_SHUFFLE_PAGE_ALLOCATOR=y introduces some unique
> locking patterns that the lockdep does not like via,
> 
> allocate_slab
>  shuffle_freelist
>    get_random_u32
> 
> Here is another splat with while compiling/installing a kernel,
> 
> [ 1254.443119][    C2] WARNING: possible circular locking dependency detected
> [ 1254.450038][    C2] 5.3.0-rc5-next-20190822 #1 Not tainted
> [ 1254.455559][    C2] ------------------------------------------------------
> [ 1254.462988][    C2] swapper/2/0 is trying to acquire lock:
> [ 1254.468509][    C2] ffffffffa2925218 (random_write_wait.lock){..-.}, at:
> __wake_up_common_lock+0xc6/0x150
> [ 1254.478154][    C2] 
> [ 1254.478154][    C2] but task is already holding lock:
> [ 1254.485896][    C2] ffff88845373fda0 (batched_entropy_u32.lock){-.-.}, at:
> get_random_u32+0x4c/0xe0
> [ 1254.495007][    C2] 
> [ 1254.495007][    C2] which lock already depends on the new lock.
> [ 1254.495007][    C2] 
> [ 1254.505331][    C2] 
> [ 1254.505331][    C2] the existing dependency chain (in reverse order) is:
> [ 1254.514755][    C2] 
> [ 1254.514755][    C2] -> #3 (batched_entropy_u32.lock){-.-.}:
> [ 1254.522553][    C2]        __lock_acquire+0x5b3/0xb40
> [ 1254.527638][    C2]        lock_acquire+0x126/0x280
> [ 1254.533016][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
> [ 1254.538624][    C2]        get_random_u32+0x4c/0xe0
> [ 1254.543539][    C2]        allocate_slab+0x6d6/0x19c0
> [ 1254.548625][    C2]        new_slab+0x46/0x70
> [ 1254.553010][    C2]        ___slab_alloc+0x58b/0x960
> [ 1254.558533][    C2]        __slab_alloc+0x43/0x70
> [ 1254.563269][    C2]        kmem_cache_alloc+0x354/0x460
> [ 1254.568534][    C2]        fill_pool+0x272/0x4b0
> [ 1254.573182][    C2]        __debug_object_init+0x86/0x7a0
> [ 1254.578615][    C2]        debug_object_init+0x16/0x20
> [ 1254.584256][    C2]        hrtimer_init+0x27/0x1e0
> [ 1254.589079][    C2]        init_dl_task_timer+0x20/0x40
> [ 1254.594342][    C2]        __sched_fork+0x10b/0x1f0
> [ 1254.599253][    C2]        init_idle+0xac/0x520
> [ 1254.603816][    C2]        fork_idle+0x18c/0x230
> [ 1254.608933][    C2]        idle_threads_init+0xf0/0x187
> [ 1254.614193][    C2]        smp_init+0x1d/0x12d
> [ 1254.618671][    C2]        kernel_init_freeable+0x37e/0x76e
> [ 1254.624282][    C2]        kernel_init+0x11/0x12f
> [ 1254.629016][    C2]        ret_from_fork+0x27/0x50
> [ 1254.634344][    C2] 
> [ 1254.634344][    C2] -> #2 (&rq->lock){-.-.}:
> [ 1254.640831][    C2]        __lock_acquire+0x5b3/0xb40
> [ 1254.645917][    C2]        lock_acquire+0x126/0x280
> [ 1254.650827][    C2]        _raw_spin_lock+0x2f/0x40
> [ 1254.655741][    C2]        task_fork_fair+0x43/0x200
> [ 1254.661213][    C2]        sched_fork+0x29b/0x420
> [ 1254.665949][    C2]        copy_process+0xf12/0x3180
> [ 1254.670947][    C2]        _do_fork+0xef/0x950
> [ 1254.675422][    C2]        kernel_thread+0xa8/0xe0
> [ 1254.680244][    C2]        rest_init+0x28/0x311
> [ 1254.685298][    C2]        arch_call_rest_init+0xe/0x1b
> [ 1254.690558][    C2]        start_kernel+0x6eb/0x724
> [ 1254.695469][    C2]        x86_64_start_reservations+0x24/0x26
> [ 1254.701339][    C2]        x86_64_start_kernel+0xf4/0xfb
> [ 1254.706689][    C2]        secondary_startup_64+0xb6/0xc0
> [ 1254.712601][    C2] 
> [ 1254.712601][    C2] -> #1 (&p->pi_lock){-.-.}:
> [ 1254.719263][    C2]        __lock_acquire+0x5b3/0xb40
> [ 1254.724349][    C2]        lock_acquire+0x126/0x280
> [ 1254.729260][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
> [ 1254.735317][    C2]        try_to_wake_up+0xad/0x1050
> [ 1254.740403][    C2]        default_wake_function+0x2f/0x40
> [ 1254.745929][    C2]        pollwake+0x10d/0x160
> [ 1254.750491][    C2]        __wake_up_common+0xc4/0x2a0
> [ 1254.755663][    C2]        __wake_up_common_lock+0xea/0x150
> [ 1254.761756][    C2]        __wake_up+0x13/0x20
> [ 1254.766230][    C2]        account.constprop.9+0x217/0x340
> [ 1254.771754][    C2]        extract_entropy.constprop.7+0xcf/0x220
> [ 1254.777886][    C2]        _xfer_secondary_pool+0x19a/0x3d0
> [ 1254.783981][    C2]        push_to_pool+0x3e/0x230
> [ 1254.788805][    C2]        process_one_work+0x52a/0xb40
> [ 1254.794064][    C2]        worker_thread+0x63/0x5b0
> [ 1254.798977][    C2]        kthread+0x1df/0x200
> [ 1254.803451][    C2]        ret_from_fork+0x27/0x50
> [ 1254.808787][    C2] 
> [ 1254.808787][    C2] -> #0 (random_write_wait.lock){..-.}:
> [ 1254.816409][    C2]        check_prev_add+0x107/0xea0
> [ 1254.821494][    C2]        validate_chain+0x8fc/0x1200
> [ 1254.826667][    C2]        __lock_acquire+0x5b3/0xb40
> [ 1254.831751][    C2]        lock_acquire+0x126/0x280
> [ 1254.837189][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
> [ 1254.842797][    C2]        __wake_up_common_lock+0xc6/0x150
> [ 1254.848408][    C2]        __wake_up+0x13/0x20
> [ 1254.852882][    C2]        account.constprop.9+0x217/0x340
> [ 1254.858988][    C2]        extract_entropy.constprop.7+0xcf/0x220
> [ 1254.865122][    C2]        crng_reseed+0xa1/0x3f0
> [ 1254.869859][    C2]        _extract_crng+0xc3/0xd0
> [ 1254.874682][    C2]        crng_reseed+0x21b/0x3f0
> [ 1254.879505][    C2]        _extract_crng+0xc3/0xd0
> [ 1254.884772][    C2]        extract_crng+0x40/0x60
> [ 1254.889507][    C2]        get_random_u32+0xb4/0xe0
> [ 1254.894417][    C2]        allocate_slab+0x6d6/0x19c0
> [ 1254.899501][    C2]        new_slab+0x46/0x70
> [ 1254.903886][    C2]        ___slab_alloc+0x58b/0x960
> [ 1254.909377][    C2]        __slab_alloc+0x43/0x70
> [ 1254.914112][    C2]        kmem_cache_alloc+0x354/0x460
> [ 1254.919375][    C2]        __build_skb+0x23/0x60
> [ 1254.924024][    C2]        __netdev_alloc_skb+0x127/0x1e0
> [ 1254.929470][    C2]        tg3_poll_work+0x11b2/0x1f70 [tg3]
> [ 1254.935654][    C2]        tg3_poll_msix+0x67/0x330 [tg3]
> [ 1254.941092][    C2]        net_rx_action+0x24e/0x7e0
> [ 1254.946089][    C2]        __do_softirq+0x123/0x767
> [ 1254.951000][    C2]        irq_exit+0xd6/0xf0
> [ 1254.955385][    C2]        do_IRQ+0xe2/0x1a0
> [ 1254.960155][    C2]        ret_from_intr+0x0/0x2a
> [ 1254.964896][    C2]        cpuidle_enter_state+0x156/0x8e0
> [ 1254.970418][    C2]        cpuidle_enter+0x41/0x70
> [ 1254.975242][    C2]        call_cpuidle+0x5e/0x90
> [ 1254.979975][    C2]        do_idle+0x333/0x370
> [ 1254.984972][    C2]        cpu_startup_entry+0x1d/0x1f
> [ 1254.990148][    C2]        start_secondary+0x290/0x330
> [ 1254.995319][    C2]        secondary_startup_64+0xb6/0xc0
> [ 1255.000750][    C2] 
> [ 1255.000750][    C2] other info that might help us debug this:
> [ 1255.000750][    C2] 
> [ 1255.011424][    C2] Chain exists of:
> [ 1255.011424][    C2]   random_write_wait.lock --> &rq->lock -->
> batched_entropy_u32.lock
> [ 1255.011424][    C2] 
> [ 1255.025245][    C2]  Possible unsafe locking scenario:
> [ 1255.025245][    C2] 
> [ 1255.033012][    C2]        CPU0                    CPU1
> [ 1255.038270][    C2]        ----                    ----
> [ 1255.043526][    C2]   lock(batched_entropy_u32.lock);
> [ 1255.048610][    C2]                                lock(&rq->lock);
> [
> 1255.054918][    C2]                                lock(batched_entropy_u32.loc
> k);
> [ 1255.063035][    C2]   lock(random_write_wait.lock);
> [ 1255.067945][    C2] 
> [ 1255.067945][    C2]  *** DEADLOCK ***
> [ 1255.067945][    C2] 
> [ 1255.076000][    C2] 1 lock held by swapper/2/0:
> [ 1255.080558][    C2]  #0: ffff88845373fda0 (batched_entropy_u32.lock){-.-.},
> at: get_random_u32+0x4c/0xe0
> [ 1255.090547][    C2] 
> [ 1255.090547][    C2] stack backtrace:
> [ 1255.096333][    C2] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 5.3.0-rc5-next-
> 20190822 #1
> [ 1255.104473][    C2] Hardware name: HPE ProLiant DL385 Gen10/ProLiant DL385
> Gen10, BIOS A40 03/09/2018
> [ 1255.114276][    C2] Call Trace:
> [ 1255.117439][    C2]  <IRQ>
> [ 1255.120169][    C2]  dump_stack+0x86/0xca
> [ 1255.124205][    C2]  print_circular_bug.cold.32+0x243/0x26e
> [ 1255.129816][    C2]  check_noncircular+0x29e/0x2e0
> [ 1255.135221][    C2]  ? __bfs+0x238/0x380
> [ 1255.139172][    C2]  ? print_circular_bug+0x120/0x120
> [ 1255.144259][    C2]  ? find_usage_forwards+0x7d/0xb0
> [ 1255.149260][    C2]  check_prev_add+0x107/0xea0
> [ 1255.153823][    C2]  validate_chain+0x8fc/0x1200
> [ 1255.159007][    C2]  ? check_prev_add+0xea0/0xea0
> [ 1255.163743][    C2]  ? check_usage_backwards+0x210/0x210
> [ 1255.169091][    C2]  __lock_acquire+0x5b3/0xb40
> [ 1255.173655][    C2]  lock_acquire+0x126/0x280
> [ 1255.178041][    C2]  ? __wake_up_common_lock+0xc6/0x150
> [ 1255.183732][    C2]  _raw_spin_lock_irqsave+0x3a/0x50
> [ 1255.188817][    C2]  ? __wake_up_common_lock+0xc6/0x150
> [ 1255.194076][    C2]  __wake_up_common_lock+0xc6/0x150
> [ 1255.199163][    C2]  ? __wake_up_common+0x2a0/0x2a0
> [ 1255.204078][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
> [ 1255.210428][    C2]  __wake_up+0x13/0x20
> [ 1255.214379][    C2]  account.constprop.9+0x217/0x340
> [ 1255.219377][    C2]  extract_entropy.constprop.7+0xcf/0x220
> [ 1255.224987][    C2]  ? crng_reseed+0xa1/0x3f0
> [ 1255.229375][    C2]  crng_reseed+0xa1/0x3f0
> [ 1255.234122][    C2]  ? rcu_read_lock_sched_held+0xac/0xe0
> [ 1255.239556][    C2]  ? check_flags.part.16+0x86/0x220
> [ 1255.244641][    C2]  ? extract_entropy.constprop.7+0x220/0x220
> [ 1255.250511][    C2]  ? __kasan_check_read+0x11/0x20
> [ 1255.255422][    C2]  ? validate_chain+0xab/0x1200
> [ 1255.260742][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
> [ 1255.266616][    C2]  _extract_crng+0xc3/0xd0
> [ 1255.270915][    C2]  crng_reseed+0x21b/0x3f0
> [ 1255.275215][    C2]  ? extract_entropy.constprop.7+0x220/0x220
> [ 1255.281085][    C2]  ? __kasan_check_write+0x14/0x20
> [ 1255.286517][    C2]  ? do_raw_spin_lock+0x118/0x1d0
> [ 1255.291428][    C2]  ? rwlock_bug.part.0+0x60/0x60
> [ 1255.296251][    C2]  _extract_crng+0xc3/0xd0
> [ 1255.300550][    C2]  extract_crng+0x40/0x60
> [ 1255.304763][    C2]  get_random_u32+0xb4/0xe0
> [ 1255.309640][    C2]  allocate_slab+0x6d6/0x19c0
> [ 1255.314203][    C2]  new_slab+0x46/0x70
> [ 1255.318066][    C2]  ___slab_alloc+0x58b/0x960
> [ 1255.322539][    C2]  ? __build_skb+0x23/0x60
> [ 1255.326841][    C2]  ? fault_create_debugfs_attr+0x140/0x140
> [ 1255.333048][    C2]  ? __build_skb+0x23/0x60
> [ 1255.337348][    C2]  __slab_alloc+0x43/0x70
> [ 1255.341559][    C2]  ? __slab_alloc+0x43/0x70
> [ 1255.345944][    C2]  ? __build_skb+0x23/0x60
> [ 1255.350242][    C2]  kmem_cache_alloc+0x354/0x460
> [ 1255.354978][    C2]  ? __netdev_alloc_skb+0x1c6/0x1e0
> [ 1255.360626][    C2]  ? trace_hardirqs_on+0x3a/0x160
> [ 1255.365535][    C2]  __build_skb+0x23/0x60
> [ 1255.369660][    C2]  __netdev_alloc_skb+0x127/0x1e0
> [ 1255.374576][    C2]  tg3_poll_work+0x11b2/0x1f70 [tg3]
> [ 1255.379750][    C2]  ? find_held_lock+0x11b/0x150
> [ 1255.385027][    C2]  ? tg3_tx_recover+0xa0/0xa0 [tg3]
> [ 1255.390114][    C2]  ? _raw_spin_unlock_irqrestore+0x38/0x50
> [ 1255.395809][    C2]  ? __kasan_check_read+0x11/0x20
> [ 1255.400718][    C2]  ? validate_chain+0xab/0x1200
> [ 1255.405455][    C2]  ? __wake_up_common+0x2a0/0x2a0
> [ 1255.410761][    C2]  ? mark_held_locks+0x34/0xb0
> [ 1255.415415][    C2]  tg3_poll_msix+0x67/0x330 [tg3]
> [ 1255.420327][    C2]  net_rx_action+0x24e/0x7e0
> [ 1255.424800][    C2]  ? find_held_lock+0x11b/0x150
> [ 1255.429536][    C2]  ? napi_busy_loop+0x600/0x600
> [ 1255.434733][    C2]  ? rcu_read_lock_sched_held+0xac/0xe0
> [ 1255.440169][    C2]  ? __do_softirq+0xed/0x767
> [ 1255.444642][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
> [ 1255.450518][    C2]  ? lockdep_hardirqs_on+0x1b0/0x2a0
> [ 1255.455693][    C2]  ? irq_exit+0xd6/0xf0
> [ 1255.460280][    C2]  __do_softirq+0x123/0x767
> [ 1255.464668][    C2]  irq_exit+0xd6/0xf0
> [ 1255.468532][    C2]  do_IRQ+0xe2/0x1a0
> [ 1255.472308][    C2]  common_interrupt+0xf/0xf
> [ 1255.476694][    C2]  </IRQ>
> [ 1255.479509][    C2] RIP: 0010:cpuidle_enter_state+0x156/0x8e0
> [ 1255.485750][    C2] Code: bf ff 8b 05 a4 27 2d 01 85 c0 0f 8f 1d 04 00 00 31
> ff e8 4d ba 92 ff 80 7d d0 00 0f 85 0b 02 00 00 e8 ae c0 a7 ff fb 45 85 ed <0f>
> 88 2d 02 00 00 4d 63 fd 49 83 ff 09 0f 87 91 06 00 00 4b 8d 04
> [ 1255.505335][    C2] RSP: 0018:ffff888206637cf8 EFLAGS: 00000202 ORIG_RAX:
> ffffffffffffffc8
> [ 1255.514154][    C2] RAX: 0000000000000000 RBX: ffff889f98b44008 RCX:
> ffffffffa116e980
> [ 1255.522033][    C2] RDX: 0000000000000007 RSI: dffffc0000000000 RDI:
> ffff8882066287ec
> [ 1255.529913][    C2] RBP: ffff888206637d48 R08: fffffbfff4557aee R09:
> 0000000000000000
> [ 1255.538278][    C2] R10: 0000000000000000 R11: 0000000000000000 R12:
> ffffffffa28e8ac0
> [ 1255.546158][    C2] R13: 0000000000000002 R14: 0000012412160253 R15:
> ffff889f98b4400c
> [ 1255.554040][    C2]  ? lockdep_hardirqs_on+0x1b0/0x2a0
> [ 1255.559725][    C2]  ? cpuidle_enter_state+0x152/0x8e0
> [ 1255.564898][    C2]  cpuidle_enter+0x41/0x70
> [ 1255.569196][    C2]  call_cpuidle+0x5e/0x90
> [ 1255.573408][    C2]  do_idle+0x333/0x370
> [ 1255.577358][    C2]  ? complete+0x51/0x60
> [ 1255.581394][    C2]  ? arch_cpu_idle_exit+0x40/0x40
> [ 1255.586777][    C2]  ? complete+0x51/0x60
> [ 1255.590814][    C2]  cpu_startup_entry+0x1d/0x1f
> [ 1255.595461][    C2]  start_secondary+0x290/0x330
> [ 1255.600111][    C2]  ? set_cpu_sibling_map+0x18f0/0x18f0
> [ 1255.605460][    C2]  secondary_startup_64+0xb6/0xc0

This looks like a false positive. shuffle_freelist() introduced the chain,

batched_entropy_u32.lock -> random_write_wait.lock

but I can’t see how it is possible to get the reversed chain. Imaging something like this,

 __wake_up_common_lock  <— acquired random_write_wait.lock
      __sched_fork <— is that even possible?
           init_dl_task_timer
              debug_object_init
                   allocate_slab
                      shuffle_freelist
                          get_random_u32 <— acquired batched_entropy_u32.lock