Dnia poniedziałek, 25 lutego 2019 19:37:37 CET piszesz:
> On Fri, 2019-02-22 at 17:37 +0100, Przemek Socha wrote:
> > [ ... ]
> > git bisect good 7cedffec8e759480f7f7a9be9cd0d7ebf0aafff2
> > # first bad commit: [986d413b7c156e69198dfc80fb74aa18d0ddef44] blk-mq:
> > Enable support for runtime power management
>
> Hi Przemek,
>
> This is weird. Neither scsi_device_quiesce() nor scsi_device_resume() are
> called by the runtime power management callbacks in the SCSI core. Whether
> or not runtime power management is enabled should not affect whether or not
> the warning in scsi_device_resume() is triggered. The only explanation I
> can think of is that a SCSI device disappeared and reappeared on the SCSI
> bus during the suspend/resume cycle. If that analysis is correct the easiest
> way to avoid that this warning appears is as follows:
>
>
> [PATCH] Avoid that system resume triggers a kernel warning
>
> This patch avoids that the following warning is triggered:
>
> WARNING: CPU: 2 PID: 11303 at drivers/scsi/scsi_lib.c:2600
> scsi_device_resume+0x4f/0x58 CPU: 2 PID: 11303 Comm: kworker/u8:70 Not
> tainted 5.0.0-rc1+ #50
> Hardware name: LENOVO 80E3/Lancer 5B2, BIOS A2CN45WW(V2.13) 08/04/2016
> Workqueue: events_unbound async_run_entry_fn
> Call Trace:
> scsi_dev_type_resume+0x2e/0x60
> async_run_entry_fn+0x32/0xd8
> process_one_work+0x1f4/0x420
> worker_thread+0x28/0x3c0
> kthread+0x118/0x130
> ret_from_fork+0x22/0x40
>
> Reported-by: Przemek Socha <soprwa@xxxxxxxxx>
> Fixes: 3a0a529971ec ("block, scsi: Make SCSI quiesce and resume work
> reliably") # v4.15 Signed-off-by: Bart Van Assche <bvanassche@xxxxxxx>
> ---
> drivers/scsi/scsi_lib.c | 1 -
> 1 file changed, 1 deletion(-)
>
> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> index c77cb0d31dbc..c73045a5f739 100644
> --- a/drivers/scsi/scsi_lib.c
> +++ b/drivers/scsi/scsi_lib.c
> @@ -2541,7 +2541,6 @@ void scsi_device_resume(struct scsi_device *sdev)
> * device deleted during suspend)
> */
> mutex_lock(&sdev->state_mutex);
> - WARN_ON_ONCE(!sdev->quiesced_by);
> sdev->quiesced_by = NULL;
> blk_clear_pm_only(sdev->request_queue);
> if (sdev->sdev_state == SDEV_QUIESCE)
Thanks Bart,
this way of suppressing the warning indeed works. Kernel log is clean (nothing
from scsi_lib or other warnings/errors from scsi subsystem).
You are right, I have enabled also pcie power management in kernel command
line "pcie_aspm=force", but warning have shown without it also.
I'm letting myself to attach a part of dmesg output with "echo -1 > /proc/sys/
dev/scsi/logging_level" taken during suspending the system.
Maybe you can figure out if this correlate with your theory. (sorry for being a
layman on this tough).
Thanks once again,
Przemek.
>>
Feb 25 20:58:12 eclipse kernel: [ 143.078119] Freezing user space processes
... (elapsed 0.002 seconds) done.
Feb 25 20:58:12 eclipse kernel: [ 143.080903] OOM killer disabled.
Feb 25 20:58:12 eclipse kernel: [ 143.080905] Freezing remaining freezable
tasks ...
Feb 25 20:58:12 eclipse kernel: [ 143.085696] sd 0:0:0:0: [sda] tag#13 Send:
scmd 0x000000004f62df31
Feb 25 20:58:12 eclipse kernel: [ 143.085702] sd 0:0:0:0: [sda] tag#13 CDB:
Write same(16) 93 08 00 00 00 00 15 bd 88 80 00 00 00 08 00 00
Feb 25 20:58:12 eclipse kernel: [ 143.085992] sd 0:0:0:0: [sda] tag#13 Done:
SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
Feb 25 20:58:12 eclipse kernel: [ 143.085997] sd 0:0:0:0: [sda] tag#13 CDB:
Write same(16) 93 08 00 00 00 00 15 bd 88 80 00 00 00 08 00 00
Feb 25 20:58:12 eclipse kernel: [ 143.086000] sd 0:0:0:0: [sda] tag#13 scsi
host busy 1 failed 0
Feb 25 20:58:12 eclipse kernel: [ 143.086005] sd 0:0:0:0: Notifying upper
driver of completion (result 0)
Feb 25 20:58:12 eclipse kernel: [ 143.086009] sd 0:0:0:0: [sda] tag#13
sd_done: completed 4096 of 512 bytes
Feb 25 20:58:12 eclipse kernel: [ 143.086014] sd 0:0:0:0: [sda] tag#13 8
sectors total, 4096 bytes done.
Feb 25 20:58:12 eclipse kernel: [ 143.089045] (elapsed 0.008 seconds) done.
Feb 25 20:58:12 eclipse kernel: [ 143.089128] printk: Suspending console(s)
(use no_console_suspend to debug)
Feb 25 20:58:12 eclipse kernel: [ 143.216878] wlp1s0: deauthenticating from
c4:12:f5:5e:4e:67 by local choice (Reason: 3=DEAUTH_LEAVING)
Feb 25 20:58:12 eclipse kernel: [ 143.242055] sd 0:0:0:0: [sda] Synchronizing
SCSI cache
Feb 25 20:58:12 eclipse kernel: [ 143.242088] sd 0:0:0:0: tag#14 Send: scmd
0x00000000c7f5d49c
Feb 25 20:58:12 eclipse kernel: [ 143.242094] sd 0:0:0:0: tag#14 CDB:
Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
Feb 25 20:58:12 eclipse kernel: [ 143.242184] sd 0:0:0:0: tag#14 Done:
SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
Feb 25 20:58:12 eclipse kernel: [ 143.242188] sd 0:0:0:0: tag#14 CDB:
Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
Feb 25 20:58:12 eclipse kernel: [ 143.242192] sd 0:0:0:0: tag#14 scsi host
busy 1 failed 0
Feb 25 20:58:12 eclipse kernel: [ 143.242197] sd 0:0:0:0: Notifying upper
driver of completion (result 0)
Feb 25 20:58:12 eclipse kernel: [ 143.242201] sd 0:0:0:0: tag#14 0 sectors
total, 0 bytes done.
Feb 25 20:58:12 eclipse kernel: [ 143.242219] sd 0:0:0:0: [sda] Stopping disk
Feb 25 20:58:12 eclipse kernel: [ 143.242229] sd 0:0:0:0: tag#15 Send: scmd
0x000000003979e83c
Feb 25 20:58:12 eclipse kernel: [ 143.242234] sd 0:0:0:0: tag#15 CDB: Start/
Stop Unit 1b 00 00 00 00 00
Feb 25 20:58:12 eclipse kernel: [ 143.272313] sd 0:0:0:0: tag#15 Done:
SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
Feb 25 20:58:12 eclipse kernel: [ 143.272322] sd 0:0:0:0: tag#15 CDB: Start/
Stop Unit 1b 00 00 00 00 00
Feb 25 20:58:12 eclipse kernel: [ 143.272327] sd 0:0:0:0: tag#15 scsi host
busy 1 failed 0
Feb 25 20:58:12 eclipse kernel: [ 143.272333] sd 0:0:0:0: Notifying upper
driver of completion (result 0)
Feb 25 20:58:12 eclipse kernel: [ 143.272338] sd 0:0:0:0: tag#15 0 sectors
total, 0 bytes done.
Feb 25 20:58:12 eclipse kernel: [ 143.278030] scsi host1: Waking error
handler thread
Feb 25 20:58:12 eclipse kernel: [ 143.278041] scsi host0: Waking error
handler thread
Feb 25 20:58:12 eclipse kernel: [ 143.278050] scsi host0: scsi_eh_0: waking
up 1/0/0
Feb 25 20:58:12 eclipse kernel: [ 143.278052] scsi host1: scsi_eh_1: waking
up 1/0/0
Feb 25 20:58:12 eclipse kernel: [ 143.278077] scsi host0: waking up host to
restart
Feb 25 20:58:12 eclipse kernel: [ 143.278083] scsi host0: scsi_eh_0: sleeping
Feb 25 20:58:12 eclipse kernel: [ 143.278091] scsi host1: waking up host to
restart
Feb 25 20:58:12 eclipse kernel: [ 143.278096] scsi host1: scsi_eh_1: sleeping
Feb 25 20:58:12 eclipse kernel: [ 143.733576] ACPI: EC: interrupt blocked
Feb 25 20:58:12 eclipse kernel: [ 143.765694] ACPI: Preparing to enter system
sleep state S3
Feb 25 20:58:12 eclipse kernel: [ 143.766442] ACPI: EC: event blocked
Feb 25 20:58:12 eclipse kernel: [ 143.766443] ACPI: EC: EC stopped
Feb 25 20:58:12 eclipse kernel: [ 143.766445] PM: Saving platform NVS memory
Feb 25 20:58:12 eclipse kernel: [ 143.769168] Disabling non-boot CPUs ...
Feb 25 20:58:12 eclipse kernel: [ 143.770994] smpboot: CPU 1 is now offline
Feb 25 20:58:12 eclipse kernel: [ 143.773343] smpboot: CPU 2 is now offline
Feb 25 20:58:12 eclipse kernel: [ 143.775591] smpboot: CPU 3 is now offline
Feb 25 20:58:12 eclipse kernel: [ 143.776431] ACPI: Low-level resume complete
Feb 25 20:58:12 eclipse kernel: [ 143.776472] ACPI: EC: EC started
Feb 25 20:58:12 eclipse kernel: [ 143.776473] PM: Restoring platform NVS
memory
Feb 25 20:58:12 eclipse kernel: [ 143.777295] LVT offset 0 assigned for vector
0x400
Feb 25 20:58:12 eclipse kernel: [ 143.777541] LVT offset 1 assigned for vector
0xf9
Feb 25 20:58:12 eclipse kernel: [ 143.777594] Enabling non-boot CPUs ...
Feb 25 20:58:12 eclipse kernel: [ 143.777663] x86: Booting SMP configuration:
Feb 25 20:58:12 eclipse kernel: [ 143.777665] smpboot: Booting Node 0
Processor 1 APIC 0x1
Feb 25 20:58:12 eclipse kernel: [ 143.780385] cache: parent cpu1 should not
be sleeping
Feb 25 20:58:12 eclipse kernel: [ 143.780462] microcode: CPU1:
patch_level=0x07030105
Feb 25 20:58:12 eclipse kernel: [ 143.780613] CPU1 is up
Feb 25 20:58:12 eclipse kernel: [ 143.780660] smpboot: Booting Node 0
Processor 2 APIC 0x2
Feb 25 20:58:12 eclipse kernel: [ 143.783221] cache: parent cpu2 should not
be sleeping
Feb 25 20:58:12 eclipse kernel: [ 143.783297] microcode: CPU2:
patch_level=0x07030105
Feb 25 20:58:12 eclipse kernel: [ 143.783479] CPU2 is up
Feb 25 20:58:12 eclipse kernel: [ 143.783526] smpboot: Booting Node 0
Processor 3 APIC 0x3
Feb 25 20:58:12 eclipse kernel: [ 143.786121] cache: parent cpu3 should not
be sleeping
Feb 25 20:58:12 eclipse kernel: [ 143.786198] microcode: CPU3:
patch_level=0x07030105
Feb 25 20:58:12 eclipse kernel: [ 143.786374] CPU3 is up
Feb 25 20:58:12 eclipse kernel: [ 143.787159] ACPI: Waking up from system
sleep state S3
Feb 25 20:58:12 eclipse kernel: [ 143.787900] ACPI: EC: interrupt unblocked
Feb 25 20:58:12 eclipse kernel: [ 143.820875] ACPI: EC: event unblocked
Feb 25 20:58:12 eclipse kernel: [ 143.821039] ath: phy0: ASPM enabled: 0x43
Feb 25 20:58:12 eclipse kernel: [ 143.821104] scsi host0: Waking error
handler thread
Feb 25 20:58:12 eclipse kernel: [ 143.821108] scsi host0: scsi_eh_0: waking
up 1/0/0
Feb 25 20:58:12 eclipse kernel: [ 143.821113] scsi host1: Waking error
handler thread
Feb 25 20:58:12 eclipse kernel: [ 143.821123] scsi host1: scsi_eh_1: waking
up 1/0/0
Feb 25 20:58:12 eclipse kernel: [ 143.829186] sd 0:0:0:0: [sda] Starting disk
Feb 25 20:58:12 eclipse kernel: [ 143.831365] ACPI: button: The lid device is
not compliant to SW_LID.
Feb 25 20:58:12 eclipse kernel: [ 143.832580] WARNING: CPU: 1 PID: 11327 at
drivers/scsi/scsi_lib.c:2600 scsi_device_resume+0x5c/0x68
Feb 25 20:58:12 eclipse kernel: [ 143.832582] Modules linked in: rfcomm
nf_tables ebtable_nat ip_set nfnetlink ebtable_filter ebtables ip6table_filter
ip6_tables overlay squashfs loop bnep ipv6 rtsx_usb_ms memstick rtsx_usb_sdmmc
ath3k btusb btintel bluetooth ecdh_generic uvcvideo videobuf2_vmalloc
videobuf2_memops videobuf2_v4l2 videobuf2_common videodev media rtsx_usb ath9k
ath9k_common ath9k_hw kvm_amd mac80211 kvm irqbypass crc32_pclmul
ghash_clmulni_intel ath sdhci_pci serio_raw cqhci sdhci amdgpu mmc_core
cfg80211 mfd_core chash gpu_sched xhci_pci xhci_hcd ttm ehci_pci ehci_hcd
sp5100_tco
Feb 25 20:58:12 eclipse kernel: [ 143.832617] CPU: 1 PID: 11327 Comm:
kworker/u8:33 Not tainted 5.0.0-rc1+ #69
Feb 25 20:58:12 eclipse kernel: [ 143.832618] Hardware name: LENOVO 80E3/
Lancer 5B2, BIOS A2CN45WW(V2.13) 08/04/2016
Feb 25 20:58:12 eclipse kernel: [ 143.832623] Workqueue: events_unbound
async_run_entry_fn
Feb 25 20:58:12 eclipse kernel: [ 143.832626] RIP:
0010:scsi_device_resume+0x5c/0x68
Feb 25 20:58:12 eclipse kernel: [ 143.832628] Code: 83 bb d0 07 00 00 05 74
0a 48 89 ef 5b 5d e9 d3 d3 25 00 48 89 df be 02 00 00 00 e8 46 fd ff ff 48 89 ef
5b 5d e9 bc d3 25 00 <0f> 0b eb be 0f 1f 84 00 00 00 00 00 eb 96 66 0f 1f 44
00 00 48 c7
Feb 25 20:58:12 eclipse kernel: [ 143.832630] RSP: 0018:ffffa4ea8203fe50
EFLAGS: 00010246
Feb 25 20:58:12 eclipse kernel: [ 143.832632] RAX: 0000000000000000 RBX:
ffff98a5d26a8000 RCX: 0000000000000000
Feb 25 20:58:12 eclipse kernel: [ 143.832633] RDX: ffff98a562c0c240 RSI:
ffffffff9a48af00 RDI: ffff98a5d26a87b0
Feb 25 20:58:12 eclipse kernel: [ 143.832634] RBP: ffff98a5d26a87b0 R08:
0000000000000008 R09: 0000646e756f626e
Feb 25 20:58:12 eclipse kernel: [ 143.832635] R10: 8080808080808080 R11:
0000000000000010 R12: ffff98a5d6816000
Feb 25 20:58:12 eclipse kernel: [ 143.832636] R13: 0000000000000000 R14:
ffff98a5d4268600 R15: 0ffff98a5d681600
Feb 25 20:58:12 eclipse kernel: [ 143.832638] FS: 0000000000000000(0000)
GS:ffff98a5d7a80000(0000) knlGS:0000000000000000
Feb 25 20:58:12 eclipse kernel: [ 143.832640] CS: 0010 DS: 0000 ES: 0000
CR0: 0000000080050033
Feb 25 20:58:12 eclipse kernel: [ 143.832641] CR2: 0000000000000000 CR3:
0000000210f3f000 CR4: 00000000000406e0
Feb 25 20:58:12 eclipse kernel: [ 143.832642] Call Trace:
Feb 25 20:58:12 eclipse kernel: [ 143.832649] scsi_dev_type_resume+0x2e/0x60
Feb 25 20:58:12 eclipse kernel: [ 143.832653] async_run_entry_fn+0x32/0xd8
Feb 25 20:58:12 eclipse kernel: [ 143.832657] process_one_work+0x1f4/0x420
Feb 25 20:58:12 eclipse kernel: [ 143.832660] worker_thread+0x28/0x3c0
Feb 25 20:58:12 eclipse kernel: [ 143.832663] ? process_one_work+0x420/0x420
Feb 25 20:58:12 eclipse kernel: [ 143.832665] kthread+0x118/0x130
Feb 25 20:58:12 eclipse kernel: [ 143.832668] ?
kthread_create_on_node+0x60/0x60
Feb 25 20:58:12 eclipse kernel: [ 143.832673] ret_from_fork+0x22/0x40
Feb 25 20:58:12 eclipse kernel: [ 143.832678] ---[ end trace 777a52c48ea2681c
]---
Feb 25 20:58:12 eclipse kernel: [ 143.834200] [drm] PCIE GART of 1024M
enabled (table at 0x000000F400000000).
Feb 25 20:58:12 eclipse kernel: [ 144.056721] usb 4-1.2: reset high-speed USB
device number 3 using ehci-pci
Feb 25 20:58:12 eclipse kernel: [ 144.056750] usb 1-1.3: reset high-speed USB
device number 3 using ehci-pci
Feb 25 20:58:12 eclipse kernel: [ 144.263494] usb 4-1.3: reset full-speed USB
device number 5 using ehci-pci
Feb 25 20:58:12 eclipse kernel: [ 144.293491] ata2: SATA link up 1.5 Gbps
(SStatus 113 SControl 300)
Feb 25 20:58:12 eclipse kernel: [ 144.293518] ata1: SATA link up 6.0 Gbps
(SStatus 133 SControl 300)
Feb 25 20:58:12 eclipse kernel: [ 144.295423] ata2.00: configured for UDMA/100
Feb 25 20:58:12 eclipse kernel: [ 144.297005] ata1.00: configured for UDMA/133
Feb 25 20:58:12 eclipse kernel: [ 144.297014] scsi host0: waking up host to
restart
<<
Attachment:
signature.asc
Description: This is a digitally signed message part.
