[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <ZpeqNohYoQI5HQP-@hovoldconsulting.com>
Date: Wed, 17 Jul 2024 13:25:42 +0200
From: Johan Hovold <johan@...nel.org>
To: Damien Le Moal <dlemoal@...nel.org>
Cc: Johan Hovold <johan+linaro@...nel.org>,
"James E.J. Bottomley" <James.Bottomley@...senPartnership.com>,
"Martin K. Petersen" <martin.petersen@...cle.com>,
Bart Van Assche <bvanassche@....org>, linux-scsi@...r.kernel.org,
linux-kernel@...r.kernel.org, stable@...r.kernel.org
Subject: Re: [PATCH] Revert "scsi: sd: Do not repeat the starting disk
message"
On Wed, Jul 17, 2024 at 07:46:14PM +0900, Damien Le Moal wrote:
> On 7/17/24 18:00, Johan Hovold wrote:
> > On Wed, Jul 17, 2024 at 07:48:26AM +0900, Damien Le Moal wrote:
> >> On 7/17/24 01:11, Johan Hovold wrote:
> >>> This reverts commit 7a6bbc2829d4ab592c7e440a6f6f5deb3cd95db4.
> >>>
> >>> The offending commit tried to suppress a double "Starting disk" message
> >>> for some drivers, but instead started spamming the log with bogus
> >>> messages every five seconds:
> >>>
> >>> [ 311.798956] sd 0:0:0:0: [sda] Starting disk
> >>> [ 316.919103] sd 0:0:0:0: [sda] Starting disk
> >>> [ 322.040775] sd 0:0:0:0: [sda] Starting disk
> >>> [ 327.161140] sd 0:0:0:0: [sda] Starting disk
> >>> [ 332.281352] sd 0:0:0:0: [sda] Starting disk
> >>> [ 337.401878] sd 0:0:0:0: [sda] Starting disk
> >>> [ 342.521527] sd 0:0:0:0: [sda] Starting disk
> >>> [ 345.850401] sd 0:0:0:0: [sda] Starting disk
> >>> [ 350.967132] sd 0:0:0:0: [sda] Starting disk
> >>> [ 356.090454] sd 0:0:0:0: [sda] Starting disk
> >>> ...
> >>>
> >>> on machines that do not actually stop the disk on runtime suspend (e.g.
> >>> the Qualcomm sc8280xp CRD with UFS).
> >>
> >> This is odd. If the disk is not being being suspended, why does the platform
> >> even enable runtime PM for it ?
> >
> > This is clearly intended to be supported as sd_do_start_stop() returns
> > false and that prevents sd_start_stop_device() from being called on
> > resume (and similarly on suspend which is why there are no matching
> > stopping disk messages above):
> >
> > [ 32.822189] sd 0:0:0:0: sd_resume_common - runtime = 1, sd_do_start_stop = 0, manage_runtime_start_stop = 0
>
> Yes, so we can suppress the "Starting disk" message for runtime resume, to match
> the runtime suspend not having the message.
No, the point is that the stopping disk message is also suppressed when
sd_do_start_stop() returns false (i.e. when sd_start_stop_device() is
never called). See sd_suspend_common().
> >> Are you sure about this ? Or is it simply that
> >> the runtime pm timer is set to a very low interval ?
> >
> > I haven't tried to determine why runtime pm is used this way, but your
> > patch is clearly broken as it prints a message about starting the disk
> > even when sd_do_start_stop() returns false.
>
> The patch is not *that* broken, because sd_do_start_stop() returning false mean
> only that the disk will *not* be started using a START STOP UNIT command. But
> the underlying LLD must start the drive. So the message is not wrong, even
> though it is probably best to suppress it for the runtime case.
>From a quick look at the code I interpret the (original) intention to be
to only print these messages in cases were sd_start_stop_device() is
actually called.
> The point here is that sd_runtime_resume() should NOT be called every 5s unless
> there is also a runtime suspend in between the calls. As mentioned, this can
> happen if the autosuspend timer is set to a very low timeout to aggressively
> suspend the disk after a short idle time. That of course makes absolutely no
> sense for HDDs given the spinup time needed, but I guess that is a possiblity
> for UFS drives.
I don't see anything obviously wrong with this for things like UFS.
Here's what some printk reveal for the Qualcomm platform in question:
[ 50.659451] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_resume
[ 50.669756] sd 0:0:0:0: sd_resume_runtime
[ 52.911603] sd 0:0:0:0: sd_suspend_runtime
[ 52.921707] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_suspend
[ 53.472894] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_resume
[ 53.481464] sd 0:0:0:0: sd_resume_runtime
[ 55.550493] sd 0:0:0:0: sd_suspend_runtime
[ 55.559697] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_suspend
[ 58.595554] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_resume
[ 58.607868] sd 0:0:0:0: sd_resume_runtime
[ 60.667330] sd 0:0:0:0: sd_suspend_runtime
[ 60.677623] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_suspend
[ 63.714149] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_resume
[ 63.724498] sd 0:0:0:0: sd_resume_runtime
[ 65.772893] sd 0:0:0:0: sd_suspend_runtime
[ 65.784696] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_suspend
[ 68.836015] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_resume
[ 68.849576] sd 0:0:0:0: sd_resume_runtime
[ 71.359102] sd 0:0:0:0: sd_suspend_runtime
[ 71.368928] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_suspend
[ 73.955031] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_resume
[ 73.963040] sd 0:0:0:0: sd_resume_runtime
[ 76.032153] sd 0:0:0:0: sd_suspend_runtime
[ 76.042100] ufs_device_wlun 0:0:0:49488: ufshcd_wl_runtime_suspend
Looks like a 2-second autosuspend timeout somewhere, and the controller
stays suspended for 1-3 seconds in between.
> >> It almost sound like what we need to do here is suppress this message for the
> >> runtime resume case, so something like:
> >
> > No, that would only make things worse as I assume you'd have a stopped
> > disk message without a matching start message for driver that do end up
> > stopping the disk here.
>
> OK. so let's revert this patch and I will rework that message to be displayed
> only on device removal, system suspend and system shutdown.
Sounds good.
Johan
Powered by blists - more mailing lists