lockdep splat during suspend

* lockdep splat during suspend
@ 2016-11-17 12:43 Borislav Petkov
  2016-11-17 16:29 ` Sebastian Andrzej Siewior
  0 siblings, 1 reply; 5+ messages in thread
From: Borislav Petkov @ 2016-11-17 12:43 UTC (permalink / raw)
  To: Sebastian Andrzej Siewior, Thomas Gleixner; +Cc: Peter Zijlstra, lkml

Hi dudes,

this is what I'm seeing on 4.9-rc5+tip/master during suspend. (And yes,
that printk thing is nuts):

[   87.471336] hib.sh (2591): drop_caches: 3
[   87.779292] PM: Syncing filesystems ... 
[   87.788772] done.
[   87.788853] Freezing user space processes ... (elapsed 0.001 seconds) done.
[   87.791447] PM: Preallocating image memory... done (allocated 105192 pages)
[   88.074812] PM: Allocated 420768 kbytes in 0.28 seconds (1502.74 MB/s)
[   88.074852] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[   88.080163] ACPI : EC: event blocked
[   88.334267] PM: freeze of devices complete after 256.808 msecs
[   88.353487] PM: late freeze of devices complete after 19.202 msecs
[   88.354728] ACPI : EC: interrupt blocked
[   88.355761] PM: noirq freeze of devices complete after 2.257 msecs
[   88.355777] Disabling non-boot CPUs ...
[   88.378463] Broke affinity for irq 16
[   88.378468] Broke affinity for irq 18
[   88.378471] Broke affinity for irq 19
[   88.379835] smpboot: CPU 1 is now offline

[   88.402872] ======================================================
[   88.402873] [ INFO: possible circular locking dependency detected ]
[   88.402874] 4.9.0-rc5+ #1 Not tainted
[   88.402875] -------------------------------------------------------
[   88.402875] hib.sh/2591 is trying to acquire lock:
[   88.402876]  (
[   88.402877] console_lock
[   88.402877] ){+.+.+.}
[   88.402883] , at: 
[   88.402883] [<ffffffff810d26de>] console_cpu_notify+0xe/0x20
[   88.402883] 
               but task is already holding lock:
[   88.402884]  (
[   88.402884] cpu_hotplug.lock
[   88.402884] ){+.+.+.}
[   88.402886] , at: 
[   88.402886] [<ffffffff8106bd52>] cpu_hotplug_begin+0x72/0xc0
[   88.402887] 
               which lock already depends on the new lock.

[   88.402887] 
               the existing dependency chain (in reverse order) is:
[   88.402888] 
               -> #3
[   88.402888]  (
[   88.402888] cpu_hotplug.lock
[   88.402889] ){+.+.+.}
[   88.402889] :
[   88.402892]        
[   88.402892] [<ffffffff810c11e2>] lock_acquire+0xb2/0x200
[   88.402895]        
[   88.402895] [<ffffffff817582c4>] mutex_lock_nested+0x54/0x600
[   88.402898]        
[   88.402898] [<ffffffff8106a063>] get_online_cpus+0x53/0x70
[   88.402901]        
[   88.402901] [<ffffffff810def14>] _rcu_barrier+0xa4/0x160
[   88.402902]        
[   88.402902] [<ffffffff810df025>] rcu_barrier+0x15/0x20
[   88.402905]        
[   88.402905] [<ffffffff8164d024>] netdev_run_todo+0x64/0x300
[   88.402907]        
[   88.402907] [<ffffffff8165a9de>] rtnl_unlock+0xe/0x10
[   88.402909]        
[   88.402909] [<ffffffffa02f6bff>] 0xffffffffa02f6bff
[   88.402910]        
[   88.402910] [<ffffffffa04e83f8>] 0xffffffffa04e83f8
[   88.402911]        
[   88.402911] [<ffffffffa04e07cb>] 0xffffffffa04e07cb
[   88.402914]        
[   88.402914] [<ffffffffa0264d29>] msr_exit+0x962/0xc39 [msr]
[   88.402914]        
[   88.402914] [<ffffffffa04f68cf>] 0xffffffffa04f68cf
[   88.402917]        
[   88.402917] [<ffffffff81103985>] SyS_delete_module+0x185/0x250
[   88.402918]        
[   88.402919] [<ffffffff8175e1ee>] entry_SYSCALL_64_fastpath+0x1c/0xb1
[   88.402919] 
               -> #2
[   88.402920]  (
[   88.402920] rcu_preempt_state.barrier_mutex
[   88.402920] ){+.+...}
[   88.402920] :
[   88.402922]        
[   88.402922] [<ffffffff810c11e2>] lock_acquire+0xb2/0x200
[   88.402924]        
[   88.402924] [<ffffffff817582c4>] mutex_lock_nested+0x54/0x600
[   88.402925]        
[   88.402925] [<ffffffff810deea6>] _rcu_barrier+0x36/0x160
[   88.402927]        
[   88.402927] [<ffffffff810df025>] rcu_barrier+0x15/0x20
[   88.402930]        
[   88.402930] [<ffffffff814b4183>] i915_gem_shrink_all+0x23/0x30
[   88.402932]        
[   88.402932] [<ffffffff814b0c4a>] i915_gem_freeze+0x2a/0x50
[   88.402935]        
[   88.402935] [<ffffffff8146ab32>] i915_pm_freeze+0x22/0x30
[   88.402938]        
[   88.402938] [<ffffffff8137c29e>] pci_pm_freeze+0x5e/0xe0
[   88.402940]        
[   88.402940] [<ffffffff81546fae>] dpm_run_callback+0x4e/0x2d0
[   88.402942]        
[   88.402942] [<ffffffff81547c56>] __device_suspend+0xf6/0x2c0
[   88.402943]        
[   88.402943] [<ffffffff81547e3f>] async_suspend+0x1f/0xa0
[   88.402945]        
[   88.402945] [<ffffffff81092237>] async_run_entry_fn+0x37/0xe0
[   88.402947]        
[   88.402947] [<ffffffff81088018>] process_one_work+0x1e8/0x730
[   88.402948]        
[   88.402948] [<ffffffff810885a8>] worker_thread+0x48/0x4e0
[   88.402950]        
[   88.402950] [<ffffffff8108ed04>] kthread+0xf4/0x110
[   88.402952]        
[   88.402952] [<ffffffff8175e477>] ret_from_fork+0x27/0x40
[   88.402952] 
               -> #1
[   88.402952]  (
[   88.402953] &dev->struct_mutex
[   88.402953] ){+.+.+.}
[   88.402953] :
[   88.402955]        
[   88.402955] [<ffffffff810c11e2>] lock_acquire+0xb2/0x200
[   88.402957]        
[   88.402957] [<ffffffff817582c4>] mutex_lock_nested+0x54/0x600
[   88.402960]        
[   88.402960] [<ffffffff8150ba85>] intel_fbdev_pan_display+0x35/0x70
[   88.402962]        
[   88.402962] [<ffffffff813a130b>] fb_pan_display+0xdb/0x170
[   88.402964]        
[   88.402964] [<ffffffff8139b870>] bit_update_start+0x20/0x50
[   88.402965]        
[   88.402965] [<ffffffff8139872f>] fbcon_switch+0x3bf/0x610
[   88.402968]        
[   88.402968] [<ffffffff814040a1>] redraw_screen+0x151/0x220
[   88.402969]        
[   88.402969] [<ffffffff81397eb6>] fbcon_do_set_font+0x246/0x3e0
[   88.402970]        
[   88.402970] [<ffffffff81398324>] fbcon_set_font+0x1f4/0x240
[   88.402972]        
[   88.402973] [<ffffffff81409209>] con_font_op+0x3e9/0x490
[   88.402974]        
[   88.402974] [<ffffffff813fb21d>] vt_ioctl+0x42d/0x13d0
[   88.402976]        
[   88.402976] [<ffffffff813eed8e>] tty_ioctl+0x3ae/0xee0
[   88.402979]        
[   88.402979] [<ffffffff812040a3>] do_vfs_ioctl+0x93/0x6a0
[   88.402980]        
[   88.402980] [<ffffffff812046f1>] SyS_ioctl+0x41/0x70
[   88.402982]        
[   88.402982] [<ffffffff8175e1ee>] entry_SYSCALL_64_fastpath+0x1c/0xb1
[   88.402982] 
               -> #0
[   88.402983]  (
[   88.402983] console_lock
[   88.402983] ){+.+.+.}
[   88.402983] :
[   88.402985]        
[   88.402985] [<ffffffff810c0b5d>] __lock_acquire+0x11cd/0x1440
[   88.402987]        
[   88.402987] [<ffffffff810c11e2>] lock_acquire+0xb2/0x200
[   88.402989]        
[   88.402989] [<ffffffff810cf77c>] console_lock+0x3c/0x60
[   88.402991]        
[   88.402991] [<ffffffff810d26de>] console_cpu_notify+0xe/0x20
[   88.402992]        
[   88.402992] [<ffffffff8106aa59>] cpuhp_invoke_callback+0xa9/0x8b0
[   88.402993]        
[   88.402993] [<ffffffff8106b472>] cpuhp_down_callbacks+0x42/0x80
[   88.402995]        
[   88.402995] [<ffffffff817532a9>] _cpu_down+0xa9/0x110
[   88.402997]        
[   88.402997] [<ffffffff8106c466>] freeze_secondary_cpus+0xb6/0x3e0
[   88.402998]        
[   88.402998] [<ffffffff810c8731>] hibernation_snapshot+0x201/0x360
[   88.403000]        
[   88.403000] [<ffffffff810c8f82>] hibernate+0x152/0x200
[   88.403001]        
[   88.403001] [<ffffffff810c5e86>] state_store+0xd6/0xe0
[   88.403003]        
[   88.403003] [<ffffffff8133f71f>] kobj_attr_store+0xf/0x20
[   88.403006]        
[   88.403006] [<ffffffff8126f645>] sysfs_kf_write+0x45/0x60
[   88.403008]        
[   88.403008] [<ffffffff8126e8f5>] kernfs_fop_write+0x135/0x1c0
[   88.403010]        
[   88.403010] [<ffffffff811ee1a8>] __vfs_write+0x28/0x120
[   88.403011]        
[   88.403011] [<ffffffff811ef2b8>] vfs_write+0xb8/0x1b0
[   88.403013]        
[   88.403013] [<ffffffff811f0609>] SyS_write+0x49/0xa0
[   88.403014]        
[   88.403014] [<ffffffff8175e1ee>] entry_SYSCALL_64_fastpath+0x1c/0xb1
[   88.403014] 
               other info that might help us debug this:

[   88.403015] Chain exists of:

[   88.403015] console_lock
[   88.403016]  --> 
[   88.403016] rcu_preempt_state.barrier_mutex
[   88.403017]  --> 
[   88.403017] cpu_hotplug.lock
[   88.403017] 

[   88.403017]  Possible unsafe locking scenario:

[   88.403018]        CPU0                    CPU1
[   88.403018]        ----                    ----
[   88.403018]   lock(
[   88.403019] cpu_hotplug.lock
[   88.403019] );
[   88.403020]                                lock(
[   88.403020] rcu_preempt_state.barrier_mutex
[   88.403020] );
[   88.403021]                                lock(
[   88.403021] cpu_hotplug.lock
[   88.403021] );
[   88.403021]   lock(
[   88.403022] console_lock
[   88.403022] );
[   88.403022] 
                *** DEADLOCK ***

[   88.403023] 8 locks held by hib.sh/2591:
[   88.403023]  #0: 
[   88.403024]  (
[   88.403024] sb_writers
[   88.403025] #5
[   88.403025] ){.+.+.+}
[   88.403026] , at: 
[   88.403026] [<ffffffff811ef394>] vfs_write+0x194/0x1b0
[   88.403026]  #1: 
[   88.403027]  (
[   88.403027] &of->mutex
[   88.403027] ){+.+.+.}
[   88.403029] , at: 
[   88.403029] [<ffffffff8126e8c1>] kernfs_fop_write+0x101/0x1c0
[   88.403029]  #2: 
[   88.403030]  (
[   88.403030] s_active
[   88.403031] #197
[   88.403031] ){.+.+.+}
[   88.403032] , at: 
[   88.403032] [<ffffffff8126e8c9>] kernfs_fop_write+0x109/0x1c0
[   88.403033]  #3: 
[   88.403033]  (
[   88.403033] pm_mutex
[   88.403034] ){+.+.+.}
[   88.403035] , at: 
[   88.403035] [<ffffffff810c8e71>] hibernate+0x41/0x200
[   88.403036]  #4: 
[   88.403036]  (
[   88.403036] device_hotplug_lock
[   88.403037] ){+.+.+.}
[   88.403038] , at: 
[   88.403038] [<ffffffff81536a77>] lock_device_hotplug+0x17/0x20
[   88.403039]  #5: 
[   88.403039]  (
[   88.403040] cpu_add_remove_lock
[   88.403040] ){+.+.+.}
[   88.403041] , at: 
[   88.403041] [<ffffffff8106c3d7>] freeze_secondary_cpus+0x27/0x3e0
[   88.403042]  #6: 
[   88.403042]  (
[   88.403042] cpu_hotplug.dep_map
[   88.403043] ){++++++}
[   88.403044] , at: 
[   88.403044] [<ffffffff8106bce5>] cpu_hotplug_begin+0x5/0xc0
[   88.403044]  #7: 
[   88.403044]  (
[   88.403045] cpu_hotplug.lock
[   88.403045] ){+.+.+.}
[   88.403046] , at: 
[   88.403046] [<ffffffff8106bd52>] cpu_hotplug_begin+0x72/0xc0
[   88.403046] 
               stack backtrace:
[   88.403048] CPU: 0 PID: 2591 Comm: hib.sh Not tainted 4.9.0-rc5+ #1
[   88.403049] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[   88.403049] Call Trace:
[   88.403053]  dump_stack+0x67/0x92
[   88.403055]  print_circular_bug+0x1e3/0x250
[   88.403056]  __lock_acquire+0x11cd/0x1440
[   88.403059]  ? debug_lockdep_rcu_enabled+0x1d/0x20
[   88.403061]  lock_acquire+0xb2/0x200
[   88.403063]  ? console_cpu_notify+0xe/0x20
[   88.403065]  ? register_console+0x380/0x380
[   88.403066]  console_lock+0x3c/0x60
[   88.403068]  ? console_cpu_notify+0xe/0x20
[   88.403069]  console_cpu_notify+0xe/0x20
[   88.403070]  cpuhp_invoke_callback+0xa9/0x8b0
[   88.403072]  ? __flow_cache_shrink+0x140/0x140
[   88.403073]  cpuhp_down_callbacks+0x42/0x80
[   88.403075]  _cpu_down+0xa9/0x110
[   88.403076]  freeze_secondary_cpus+0xb6/0x3e0
[   88.403077]  hibernation_snapshot+0x201/0x360
[   88.403078]  hibernate+0x152/0x200
[   88.403080]  state_store+0xd6/0xe0
[   88.403081]  kobj_attr_store+0xf/0x20
[   88.403082]  sysfs_kf_write+0x45/0x60
[   88.403084]  kernfs_fop_write+0x135/0x1c0
[   88.403086]  __vfs_write+0x28/0x120
[   88.403087]  ? preempt_count_sub+0xa1/0x110
[   88.403089]  ? __sb_start_write+0xea/0x200
[   88.403090]  ? vfs_write+0x194/0x1b0
[   88.403091]  vfs_write+0xb8/0x1b0
[   88.403092]  ? trace_hardirqs_on_caller+0x12d/0x1b0
[   88.403093]  SyS_write+0x49/0xa0
[   88.403095]  entry_SYSCALL_64_fastpath+0x1c/0xb1
[   88.403096] RIP: 0033:0x7f37f6dc51c0
[   88.403097] RSP: 002b:00007ffe98060948 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[   88.403098] RAX: ffffffffffffffda RBX: 0000000000000046 RCX: 00007f37f6dc51c0
[   88.403098] RDX: 0000000000000005 RSI: 00000000013f5408 RDI: 0000000000000001
[   88.403099] RBP: 0000000000000004 R08: 00007f37f7088780 R09: 00007f37f78d8700
[   88.403100] R10: 0000000000000004 R11: 0000000000000246 R12: 00000000004be368
[   88.403100] R13: 0000000000002002 R14: 00000000013fe400 R15: 0000000000000070
[   88.417290] Broke affinity for irq 16
[   88.417293] Broke affinity for irq 18
[   88.417295] Broke affinity for irq 19
[   88.418315] smpboot: CPU 2 is now offline
[   88.461454] Broke affinity for irq 1
[   88.461460] Broke affinity for irq 8
[   88.461464] Broke affinity for irq 9
[   88.461468] Broke affinity for irq 12
[   88.461473] Broke affinity for irq 16
[   88.461477] Broke affinity for irq 18
[   88.461480] Broke affinity for irq 19
[   88.461485] Broke affinity for irq 23
[   88.461489] Broke affinity for irq 26
[   88.461493] Broke affinity for irq 27
[   88.462528] smpboot: CPU 3 is now offline
[   88.473978] PM: Creating hibernation image:
[   88.733315] PM: Need to copy 104116 pages
[   88.475760] Suspended for 19.000 seconds
[   88.475851] Enabling non-boot CPUs ...
[   88.487470] x86: Booting SMP configuration:
[   88.487479] smpboot: Booting Node 0 Processor 1 APIC 0x1
[   88.492153]  cache: parent cpu1 should not be sleeping
[   88.492571] CPU1 is up
[   88.507516] smpboot: Booting Node 0 Processor 2 APIC 0x2
[   88.511244]  cache: parent cpu2 should not be sleeping
[   88.511626] CPU2 is up
[   88.527572] smpboot: Booting Node 0 Processor 3 APIC 0x3
[   88.531225]  cache: parent cpu3 should not be sleeping
[   88.531617] CPU3 is up
[   88.537517] ACPI : EC: interrupt unblocked
[   88.540582] sdhci-pci 0000:02:00.0: MMC controller base frequency changed to 50Mhz.
[   88.583150] PM: noirq restore of devices complete after 45.897 msecs
[   88.583639] PM: early restore of devices complete after 0.459 msecs
[   88.625421] usb usb1: root hub lost power or was reset
[   88.625432] usb usb2: root hub lost power or was reset
[   88.625608] usb usb3: root hub lost power or was reset
[   88.625883] usb usb4: root hub lost power or was reset
[   88.626879] ACPI : button: The lid device is not compliant to SW_LID.
[   88.626910] ACPI : EC: event unblocked
[   88.627295] rtc_cmos 00:02: System wakeup disabled by ACPI
[   88.629508] ehci-pci 0000:00:1a.0: cache line size of 64 is not supported
[   88.629783] ehci-pci 0000:00:1d.0: cache line size of 64 is not supported
[   88.636192] sd 2:0:0:0: [sdb] Starting disk
[   88.636228] sd 0:0:0:0: [sda] Starting disk
[   88.963083] usb 4-1: reset high-speed USB device number 2 using ehci-pci
[   88.963085] usb 3-1: reset high-speed USB device number 2 using ehci-pci
[   88.974052] ata5: SATA link down (SStatus 0 SControl 300)
[   88.974093] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[   88.974136] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[   88.974583] ata3.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[   88.974596] ata3.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[   88.975119] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[   88.975132] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[   88.975549] ata3.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[   88.975562] ata3.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[   88.975887] ata3.00: configured for UDMA/100
[   88.977083] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[   88.977112] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[   88.977937] ata1.00: configured for UDMA/133
[   89.671711] PM: restore of devices complete after 1046.321 msecs
[   89.673226] Restarting tasks ... done.
[   89.673738] usb 1-1: USB disconnect, device number 2
[   89.823083] usb 1-1: new low-speed USB device number 3 using xhci_hcd
[   89.969125] usb 1-1: New USB device found, idVendor=046d, idProduct=c045
[   89.969135] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[   89.969141] usb 1-1: Product: USB-PS/2 Optical Mouse
[   89.969146] usb 1-1: Manufacturer: Logitech
[   89.974053] input: Logitech USB-PS/2 Optical Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0/0003:046D:C045.0002/input/input20
[   90.031487] hid-generic 0003:046D:C045.0002: input,hidraw0: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:14.0-1/input0
[   90.340587] psmouse serio1: synaptics: queried max coordinates: x [..5768], y [..5062]
[   90.371618] psmouse serio1: synaptics: queried min coordinates: x [1174..], y [790..]
[   90.421219] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx

-- 
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.

^ permalink raw reply	[flat|nested] 5+ messages in thread