ata,scsi: do not issue START STOP UNIT on resume

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

---
  drivers/ata/libata-scsi.c  | 7 +++++++
  drivers/scsi/sd.c          | 9 ++++++---
  include/scsi/scsi_device.h | 1 +
  3 files changed, 14 insertions(+), 3 deletions(-)

drivers/ata/libata-scsi.c +7 -0

index 370d18aca71e..c6ece32de8e3 100644
@@ -1100,7 +1100,14 @@ int ata_scsi_dev_config(struct scsi_device *sdev, struct ata_device *dev)
  		}
  	} else {
  		sdev->sector_size = ata_id_logical_sector_size(dev->id);
+		/*
+		 * Stop the drive on suspend but do not issue START STOP UNIT
+		 * on resume as this is not necessary and may fail: the device
+		 * will be woken up by ata_port_pm_resume() with a port reset
+		 * and device revalidation.
+		 */
  		sdev->manage_start_stop = 1;
+		sdev->no_start_on_resume = 1;
  	}
 
  	/*

drivers/scsi/sd.c +6 -3

index 68b12afa0721..3c668cfb146d 100644
@@ -3876,7 +3876,7 @@ static int sd_suspend_runtime(struct device *dev)
  static int sd_resume(struct device *dev)
  {
  	struct scsi_disk *sdkp = dev_get_drvdata(dev);
-	int ret;
+	int ret = 0;
 
  	if (!sdkp)	/* E.g.: runtime resume at the start of sd_probe() */
  		return 0;

@@ -3884,8 +3884,11 @@ static int sd_resume(struct device *dev)
  	if (!sdkp->device->manage_start_stop)
  		return 0;
 
-	sd_printk(KERN_NOTICE, sdkp, "Starting disk\n");
-	ret = sd_start_stop_device(sdkp, 1);
+	if (!sdkp->device->no_start_on_resume) {
+		sd_printk(KERN_NOTICE, sdkp, "Starting disk\n");
+		ret = sd_start_stop_device(sdkp, 1);
+	}
+
  	if (!ret)
  		opal_unlock_from_suspend(sdkp->opal_dev);
  	return ret;

include/scsi/scsi_device.h +1 -0

index 75b2235b99e2..b9230b6add04 100644
@@ -194,6 +194,7 @@ struct scsi_device {
  	unsigned no_start_on_add:1;	/* do not issue start on add */
  	unsigned allow_restart:1; /* issue START_UNIT in error handler */
  	unsigned manage_start_stop:1;	/* Let HLD (sd) manage start/stop */
+	unsigned no_start_on_resume:1; /* Do not issue START_STOP_UNIT on resume */
  	unsigned start_stop_pwr_cond:1;	/* Set power cond. in START_STOP_UNIT */
  	unsigned no_uld_attach:1; /* disable connecting to upper level drivers */
  	unsigned select_no_atn:1;

Tested-by Tanner Watkins

Quoted 105 lines

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

---
  drivers/ata/libata-scsi.c  | 7 +++++++
  drivers/scsi/sd.c          | 9 ++++++---
  include/scsi/scsi_device.h | 1 +
  3 files changed, 14 insertions(+), 3 deletions(-)

drivers/ata/libata-scsi.c +7 -0

index 370d18aca71e..c6ece32de8e3 100644
@@ -1100,7 +1100,14 @@ int ata_scsi_dev_config(struct scsi_device *sdev, struct ata_device *dev)
  		}
  	} else {
  		sdev->sector_size = ata_id_logical_sector_size(dev->id);
+		/*
+		 * Stop the drive on suspend but do not issue START STOP UNIT
+		 * on resume as this is not necessary and may fail: the device
+		 * will be woken up by ata_port_pm_resume() with a port reset
+		 * and device revalidation.
+		 */
  		sdev->manage_start_stop = 1;
+		sdev->no_start_on_resume = 1;
  	}
 
  	/*

drivers/scsi/sd.c +6 -3

index 68b12afa0721..3c668cfb146d 100644
@@ -3876,7 +3876,7 @@ static int sd_suspend_runtime(struct device *dev)
  static int sd_resume(struct device *dev)
  {
  	struct scsi_disk *sdkp = dev_get_drvdata(dev);
-	int ret;
+	int ret = 0;
 
  	if (!sdkp)	/* E.g.: runtime resume at the start of sd_probe() */
  		return 0;

@@ -3884,8 +3884,11 @@ static int sd_resume(struct device *dev)
  	if (!sdkp->device->manage_start_stop)
  		return 0;
 
-	sd_printk(KERN_NOTICE, sdkp, "Starting disk\n");
-	ret = sd_start_stop_device(sdkp, 1);
+	if (!sdkp->device->no_start_on_resume) {
+		sd_printk(KERN_NOTICE, sdkp, "Starting disk\n");
+		ret = sd_start_stop_device(sdkp, 1);
+	}
+
  	if (!ret)
  		opal_unlock_from_suspend(sdkp->opal_dev);
  	return ret;

include/scsi/scsi_device.h +1 -0

index 75b2235b99e2..b9230b6add04 100644
@@ -194,6 +194,7 @@ struct scsi_device {
  	unsigned no_start_on_add:1;	/* do not issue start on add */
  	unsigned allow_restart:1; /* issue START_UNIT in error handler */
  	unsigned manage_start_stop:1;	/* Let HLD (sd) manage start/stop */
+	unsigned no_start_on_resume:1; /* Do not issue START_STOP_UNIT on resume */
  	unsigned start_stop_pwr_cond:1;	/* Set power cond. in START_STOP_UNIT */
  	unsigned no_uld_attach:1; /* disable connecting to upper level drivers */
  	unsigned select_no_atn:1;

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

---
  drivers/ata/libata-scsi.c  | 7 +++++++
  drivers/scsi/sd.c          | 9 ++++++---
  include/scsi/scsi_device.h | 1 +
  3 files changed, 14 insertions(+), 3 deletions(-)

drivers/ata/libata-scsi.c +7 -0

index 370d18aca71e..c6ece32de8e3 100644
@@ -1100,7 +1100,14 @@ int ata_scsi_dev_config(struct scsi_device *sdev, struct ata_device *dev)
  		}
  	} else {
  		sdev->sector_size = ata_id_logical_sector_size(dev->id);
+		/*
+		 * Stop the drive on suspend but do not issue START STOP UNIT
+		 * on resume as this is not necessary and may fail: the device
+		 * will be woken up by ata_port_pm_resume() with a port reset
+		 * and device revalidation.
+		 */
  		sdev->manage_start_stop = 1;
+		sdev->no_start_on_resume = 1;
  	}
 
  	/*

drivers/scsi/sd.c +6 -3

index 68b12afa0721..3c668cfb146d 100644
@@ -3876,7 +3876,7 @@ static int sd_suspend_runtime(struct device *dev)
  static int sd_resume(struct device *dev)
  {
  	struct scsi_disk *sdkp = dev_get_drvdata(dev);
-	int ret;
+	int ret = 0;
 
  	if (!sdkp)	/* E.g.: runtime resume at the start of sd_probe() */
  		return 0;

@@ -3884,8 +3884,11 @@ static int sd_resume(struct device *dev)
  	if (!sdkp->device->manage_start_stop)
  		return 0;
 
-	sd_printk(KERN_NOTICE, sdkp, "Starting disk\n");
-	ret = sd_start_stop_device(sdkp, 1);
+	if (!sdkp->device->no_start_on_resume) {
+		sd_printk(KERN_NOTICE, sdkp, "Starting disk\n");
+		ret = sd_start_stop_device(sdkp, 1);
+	}
+
  	if (!ret)
  		opal_unlock_from_suspend(sdkp->opal_dev);
  	return ret;

include/scsi/scsi_device.h +0 -0

index 75b2235b99e2..b9230b6add04 100644

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Quoted 30 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Quoted 7 lines

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Q: As libata starts up the drive internally via reset/revalidate, why do we have to sent START STOP UNIT for shutdown?

Wouldn't it be better to disable START STOP UNIT completely for libata, and let everything be handled via ATA command (IDLE IMMEDIATE, SLEEP) ? Hmm?

Otherwise a really good idea. We've fallen into this trap several times ourselves.
Incidentally, USB could benefit from the same mechanism ...

Cheers,

Hannes

Quoted 38 lines · Hannes Reinecke

Quoted 30 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Quoted 7 lines

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Quoted 2 lines

Q: As libata starts up the drive internally via reset/revalidate, why do we have to sent START STOP UNIT for shutdown?

To spin down the drive and put it to sleep.

Quoted 3 lines

Wouldn't it be better to disable START STOP UNIT completely for libata, and let everything be handled via ATA command (IDLE IMMEDIATE, SLEEP) ? Hmm?

I am not sure this buys us much. Could try though, but that is a little too much changes for a bug fix for this cycle.

I think we need to think about that in the context of reworking ata suspend/resume to be correct with regard to synchronizing ata device and scsi device suspend/resume with a direct device link, which we do not have right now.

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Reported-by Paul Ausbeck<[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal<[email protected]>

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

---
 drivers/ata/libata-scsi.c  | 7 +++++++
 drivers/scsi/sd.c          | 9 ++++++---
 include/scsi/scsi_device.h | 1 +
 3 files changed, 14 insertions(+), 3 deletions(-)

drivers/ata/libata-scsi.c +7 -0

index 370d18aca71e..c6ece32de8e3 100644
@@ -1100,7 +1100,14 @@ int ata_scsi_dev_config(struct scsi_device *sdev, struct ata_device *dev)
 		}
 	} else {
 		sdev->sector_size = ata_id_logical_sector_size(dev->id);
+		/*
+		 * Stop the drive on suspend but do not issue START STOP UNIT
+		 * on resume as this is not necessary and may fail: the device
+		 * will be woken up by ata_port_pm_resume() with a port reset
+		 * and device revalidation.
+		 */
 		sdev->manage_start_stop = 1;
+		sdev->no_start_on_resume = 1;
 	}
 
 	/*

drivers/scsi/sd.c +6 -3

index 68b12afa0721..3c668cfb146d 100644
@@ -3876,7 +3876,7 @@ static int sd_suspend_runtime(struct device *dev)
 static int sd_resume(struct device *dev)
 {
 	struct scsi_disk *sdkp = dev_get_drvdata(dev);
-	int ret;
+	int ret = 0;
 
 	if (!sdkp)	/* E.g.: runtime resume at the start of sd_probe() */
 		return 0;

@@ -3884,8 +3884,11 @@ static int sd_resume(struct device *dev)
 	if (!sdkp->device->manage_start_stop)
 		return 0;
 
-	sd_printk(KERN_NOTICE, sdkp, "Starting disk\n");
-	ret = sd_start_stop_device(sdkp, 1);
+	if (!sdkp->device->no_start_on_resume) {
+		sd_printk(KERN_NOTICE, sdkp, "Starting disk\n");
+		ret = sd_start_stop_device(sdkp, 1);
+	}
+
 	if (!ret)
 		opal_unlock_from_suspend(sdkp->opal_dev);
 	return ret;

include/scsi/scsi_device.h +1 -0

index 75b2235b99e2..b9230b6add04 100644
@@ -194,6 +194,7 @@ struct scsi_device {
 	unsigned no_start_on_add:1;	/* do not issue start on add */
 	unsigned allow_restart:1; /* issue START_UNIT in error handler */
 	unsigned manage_start_stop:1;	/* Let HLD (sd) manage start/stop */
+	unsigned no_start_on_resume:1; /* Do not issue START_STOP_UNIT on resume */
 	unsigned start_stop_pwr_cond:1;	/* Set power cond. in START_STOP_UNIT */
 	unsigned no_uld_attach:1; /* disable connecting to upper level drivers */
 	unsigned select_no_atn:1;

Signature · 1 line

2.41.0

Quoted 30 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Quoted 6 lines

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Hi Damien,

Last week I noticed that a basic test in our validation started failing, then I noticed that it was subsequent quick suspend and autoresume using rtcwake that was problematic.

I couldn't collect any specific log that was pointing to some useful direction. After a painful bisect I got to this patch. After reverting in from the top of our tree, the tests are back to life.

The issue was that the subsequent quick suspend-resume (sometimes the second, sometimes third or even sixth) was simply hanging the machine in different points at Suspend.

So, maybe we have some kind of disks/configuration out there where this start upon resume is needed? Maybe it is just a matter of timming to ensure some firmware underneath is up and back to life?

Well, please let me know the best way to report this issue to you and what kind of logs I should get.

The main issue I think is that there is no direct ancestry between the ata port (device) and scsi device,

Damien,

Quoted 2 lines

The main issue I think is that there is no direct ancestry between the ata port (device) and scsi device,

I really think this should be fixed. It is a major deficiency as far as I'm concerned and it affects other things than power management.

Quoted 38 lines · Rodrigo Vivi

Quoted 30 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Quoted 6 lines

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Quoted 5 lines

Hi Damien,

Last week I noticed that a basic test in our validation started failing, then I noticed that it was subsequent quick suspend and autoresume using rtcwake that was problematic.

Arg... Again... Since the change of scsi layer to use async PM operations for suspend/resume, ATA side has been a constant source of issues. When the change was done, I did not notice any issue but several users reported problems.

Quoted 4 lines

I couldn't collect any specific log that was pointing to some useful direction. After a painful bisect I got to this patch. After reverting in from the top of our tree, the tests are back to life.

Quoted 3 lines

The issue was that the subsequent quick suspend-resume (sometimes the second, sometimes third or even sixth) was simply hanging the machine in different points at Suspend.

I would have expected issues on the resume side. But it seems you are getting a hang on suspend, which is new. How quick are your suspend/resume cycles ? I did use rtcqake for my tests as well, but I was setting the wake timer at +5s or more and suspending with "systemctl suspend".

Quoted 4 lines

So, maybe we have some kind of disks/configuration out there where this start upon resume is needed? Maybe it is just a matter of timming to ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive to sleep and resume will reset the port (which should wake up the drive) and then issue an IDENTIFY command (which will also wake up the drive) and other read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and likely port reset/drive gone events. So I think this is likely another subtle race between scsi suspend and ata suspend that is causing a deadlock.

The main issue I think is that there is no direct ancestry between the ata port (device) and scsi device, so the change to scsi async pm ops made a mess of the suspend/resume operations ordering. For suspend, scsi device (child of ata port) should be first, then ata port device (parent). For resume, the reverse order is needed. PM normally ensures that parent/child ordering, but we lack that parent/child relationship. I am working on fixing that but it is very slow progress because I have been so far enable to recreate any of the issues that have been reported. I am patching "blind"...

Any chance you could get a thread stack dump when the system hangs ?

echo t > /proc/sysrq-trigger

And:

echo d > /proc/sysrq-trigger

would be useful as well...

That is, unless you really have a hard lockup...

Quoted 3 lines

Well, please let me know the best way to report this issue to you and what kind of logs I should get.

If you can get the above ? dmesg output as well with PM debug messages turned on.

Also, what is your setup ? What machine, adapter and drive are you using ?

Signature · 3 lines

-- 
Damien Le Moal
Western Digital Research

Quoted 4 lines

I would have expected issues on the resume side. But it seems you are getting a hang on suspend, which is new. How quick are your suspend/resume cycles ? I did use rtcqake for my tests as well, but I was setting the wake timer at +5s or more and suspending with "systemctl suspend".

I meant resume. It hangs during random parts at the resume sequence. Brain thought resume, fingers typed 'Suspend', I'm sorry!

Quoted 12 lines

Quoted 3 lines

So, maybe we have some kind of disks/configuration out there where this start upon resume is needed? Maybe it is just a matter of timming to ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive to sleep and resume will reset the port (which should wake up the drive) and then issue an IDENTIFY command (which will also wake up the drive) and other read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and likely port reset/drive gone events. So I think this is likely another subtle race between scsi suspend and ata suspend that is causing a deadlock.

Quoted 8 lines

The main issue I think is that there is no direct ancestry between the ata port (device) and scsi device, so the change to scsi async pm ops made a mess of the suspend/resume operations ordering. For suspend, scsi device (child of ata port) should be first, then ata port device (parent). For resume, the reverse order is needed. PM normally ensures that parent/child ordering, but we lack that parent/child relationship. I am working on fixing that but it is very slow progress because I have been so far enable to recreate any of the issues that have been reported. I am patching "blind"...

I believe your suspicious makes sense. And on these lines, that patch you attached earlier would fix that. However my initial tries of that didn't help. I'm going to run more tests and get back to you.

Quoted 6 lines

Any chance you could get a thread stack dump when the system hangs ?

echo t > /proc/sysrq-trigger

And:

Quoted 5 lines

echo d > /proc/sysrq-trigger

would be useful as well...

That is, unless you really have a hard lockup...

no chance... it is a hard lockup.

I have the CONFIG_PM_DEBUG here with no_console_suspend.
If you remember any other config or parameter that would help, please let me know that I collect it again:

[  104.571459] PM: suspend entry (deep)
[  104.585967] Filesystems sync: 0.010 seconds
[  104.618685] Freezing user space processes
[  104.625374] Freezing user space processes completed (elapsed 0.002 seconds)
[  104.632448] OOM killer disabled.
[  104.635712] Freezing remaining freezable tasks
[  104.641899] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  104.669767] wlp6s0: deauthenticating from 08:36:c9:85:df:ef by local choice (Reason: 3=DEAUTH_LEAVING)
[  104.679812] serial 00:01: disabled
[  104.683466] sd 7:0:0:0: [sdc] Synchronizing SCSI cache
[  104.688902] sd 7:0:0:0: [sdc] Stopping disk
[  104.693176] sd 5:0:0:0: [sdb] Synchronizing SCSI cache
[  104.698419] sd 4:0:0:0: [sda] Synchronizing SCSI cache
[  104.703730] sd 4:0:0:0: [sda] Stopping disk
[  104.885912] sd 5:0:0:0: [sdb] Stopping disk

[  106.163215] PM: suspend devices took 1.514 seconds
[  107.003217] serial 00:01: activated
[  107.076779] nvme nvme0: 16/0/0 default/read/poll queues
[  107.123917] r8169 0000:07:00.0 enp7s0: Link is Down
[  107.208945] PM: resume devices took 0.241 seconds
[  107.214746] pcieport 0000:00:1c.0: PCI bridge to [bus 06]
[  107.220274] pcieport 0000:00:1c.0:   bridge window [mem 0x43700000-0x437fffff]
[  107.227538] OOM killer enabled.
[  107.230710] Restarting tasks ...
[  107.231803] pcieport 0000:00:1c.2: PCI bridge to [bus 07]
[  107.236474] done.

[  107.240599] pcieport 0000:00:1c.2:   bridge window [io  0x4000-0x4fff]
[  107.242574] random: crng reseeded on system resumption
[  107.249119] pcieport 0000:00:1c.2:   bridge window [mem 0x43600000-0x436fffff]
[  107.249405] pcieport 0000:00:1c.6: PCI bridge to [bus 08]
[  107.259714] PM: suspend exit
[  107.261623] pcieport 0000:00:1c.6:   bridge window [io  0x3000-0x3fff]
[  107.276554] pcieport 0000:00:1c.6:   bridge window [mem 0x43500000-0x435fffff]
[  107.283849] pcieport 0000:00:1c.6:   bridge window [mem 0x70900000-0x709fffff 64bit pref]

[  107.293567] ata7: SATA link down (SStatus 4 SControl 300)
[  107.304150] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  107.310975] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  107.319173] ata5.00: configured for UDMA/133
[  107.324620] ata5.00: Enabling discard_zeroes_data
[  107.398370] ata6.00: configured for UDMA/133

[  108.563229] PM: suspend entry (deep)
[  108.573610] Filesystems sync: 0.006 seconds
[  108.580617] Freezing user space processes
[  108.586774] Freezing user space processes completed (elapsed 0.002 seconds)
[  108.593793] OOM killer disabled.
[  108.597055] Freezing remaining freezable tasks
[  108.603246] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)

[  108.621515] sd 7:0:0:0: [sdc] Synchronizing SCSI cache
[  108.621522] sd 5:0:0:0: [sdb] Synchronizing SCSI cache
[  108.622018] serial 00:01: disabled
[  108.635420] sd 4:0:0:0: [sda] Synchronizing SCSI cache
[  108.640747] sd 4:0:0:0: [sda] Stopping disk
[  108.644148] sd 5:0:0:0: [sdb] Stopping disk
[  108.983487] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  108.991923] ata8.00: configured for UDMA/133

[  108.996423] sd 7:0:0:0: [sdc] Stopping disk
[  109.973722] PM: suspend devices took 1.363 seconds
[  110.721600] serial 00:01: activated
[  110.802094] nvme nvme0: 16/0/0 default/read/poll queues
[  110.873036] r8169 0000:07:00.0 enp7s0: Link is Down

[  111.032278] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  111.038583] ata7: SATA link down (SStatus 4 SControl 300)
[  111.044065] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  111.051326] ata5.00: configured for UDMA/133
[  111.056118] ata5.00: Enabling discard_zeroes_data
[  111.131795] ata6.00: configured for UDMA/133
[  112.713764] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  112.724250] ata8.00: configured for UDMA/133

Quoted 12 lines

Quoted 3 lines

So, maybe we have some kind of disks/configuration out there where this start upon resume is needed? Maybe it is just a matter of timming to ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive to sleep and resume will reset the port (which should wake up the drive) and then issue an IDENTIFY command (which will also wake up the drive) and other read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and likely port reset/drive gone events. So I think this is likely another subtle race between scsi suspend and ata suspend that is causing a deadlock.

Quoted 8 lines

The main issue I think is that there is no direct ancestry between the ata port (device) and scsi device, so the change to scsi async pm ops made a mess of the suspend/resume operations ordering. For suspend, scsi device (child of ata port) should be first, then ata port device (parent). For resume, the reverse order is needed. PM normally ensures that parent/child ordering, but we lack that parent/child relationship. I am working on fixing that but it is very slow progress because I have been so far enable to recreate any of the issues that have been reported. I am patching "blind"...

I believe your suspicious makes sense. And on these lines, that patch you attached earlier would fix that. However my initial tries of that didn't help. I'm going to run more tests and get back to you.

Quoted 21 lines · Rodrigo Vivi

Quoted 12 lines

Quoted 3 lines

So, maybe we have some kind of disks/configuration out there where this start upon resume is needed? Maybe it is just a matter of timming to ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive to sleep and resume will reset the port (which should wake up the drive) and then issue an IDENTIFY command (which will also wake up the drive) and other read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and likely port reset/drive gone events. So I think this is likely another subtle race between scsi suspend and ata suspend that is causing a deadlock.

Quoted 8 lines

The main issue I think is that there is no direct ancestry between the ata port (device) and scsi device, so the change to scsi async pm ops made a mess of the suspend/resume operations ordering. For suspend, scsi device (child of ata port) should be first, then ata port device (parent). For resume, the reverse order is needed. PM normally ensures that parent/child ordering, but we lack that parent/child relationship. I am working on fixing that but it is very slow progress because I have been so far enable to recreate any of the issues that have been reported. I am patching "blind"...

Quoted 3 lines

I believe your suspicious makes sense. And on these lines, that patch you attached earlier would fix that. However my initial tries of that didn't help. I'm going to run more tests and get back to you.

Rodrigo,

I pushed the resume-v2 branch to libata tree:

[email protected]:pub/scm/linux/kernel/git/dlemoal/libata (or https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.git)

This branch adds 13 patches on top of 6.5.0 to cleanup libata suspend/resume and other device shutdown issues. The first 4 patches are the main ones to fix suspend resume. I tested that on 2 different machines with different drives and with qemu. All seems fine.

Could you try to run this through your CI ? I am very interested in seeing if it survives your suspend/resume tests.

If you can confirm that all issues are fixed, I will rebase this on for-next and post.

Thanks !

Signature · 2 lines

Damien Le Moal
Western Digital Research

Quoted 33 lines · Damien Le Moal

Quoted 21 lines · Rodrigo Vivi

Quoted 12 lines

Quoted 3 lines

So, maybe we have some kind of disks/configuration out there where this start upon resume is needed? Maybe it is just a matter of timming to ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive to sleep and resume will reset the port (which should wake up the drive) and then issue an IDENTIFY command (which will also wake up the drive) and other read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and likely port reset/drive gone events. So I think this is likely another subtle race between scsi suspend and ata suspend that is causing a deadlock.

Quoted 8 lines

The main issue I think is that there is no direct ancestry between the ata port (device) and scsi device, so the change to scsi async pm ops made a mess of the suspend/resume operations ordering. For suspend, scsi device (child of ata port) should be first, then ata port device (parent). For resume, the reverse order is needed. PM normally ensures that parent/child ordering, but we lack that parent/child relationship. I am working on fixing that but it is very slow progress because I have been so far enable to recreate any of the issues that have been reported. I am patching "blind"...

Quoted 3 lines

I believe your suspicious makes sense. And on these lines, that patch you attached earlier would fix that. However my initial tries of that didn't help. I'm going to run more tests and get back to you.

Rodrigo,

I pushed the resume-v2 branch to libata tree:

[email protected]:pub/scm/linux/kernel/git/dlemoal/libata (or https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.git)

Quoted 7 lines

This branch adds 13 patches on top of 6.5.0 to cleanup libata suspend/resume and other device shutdown issues. The first 4 patches are the main ones to fix suspend resume. I tested that on 2 different machines with different drives and with qemu. All seems fine.

Could you try to run this through your CI ? I am very interested in seeing if it survives your suspend/resume tests.

well, in the end this didn't affect the CI machinery as I was afraid. it is only in my local DG2.

https://intel-gfx-ci.01.org/tree/intel-xe/bat-all.html?testfilter=suspend
(bat-dg2-oem2 one)

I just got these 13 patches and applied to my branch and tested it again and it still *fails* for me.

[   79.648328] [IGT] kms_pipe_crc_basic: finished subtest pipe-A-DP-2, SUCCESS
[   79.657353] [IGT] kms_pipe_crc_basic: starting dynamic subtest pipe-B-DP-2
[   80.375042] PM: suspend entry (deep)
[   80.380799] Filesystems sync: 0.002 seconds
[   80.386476] Freezing user space processes
[   80.392286] Freezing user space processes completed (elapsed 0.001 seconds)
[   80.399294] OOM killer disabled.
[   80.402536] Freezing remaining freezable tasks
[   80.408335] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[   80.439372] sd 5:0:0:0: [sdb] Synchronizing SCSI cache
[   80.439716] serial 00:01: disabled
[   80.448011] sd 4:0:0:0: [sda] Synchronizing SCSI cache
[   80.448014] sd 7:0:0:0: [sdc] Synchronizing SCSI cache
[   80.453600] ata6.00: Entering standby power mode

[   80.464217] ata5.00: Entering standby power mode

[   80.812294] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[   80.818520] ata8.00: Entering active power mode
[   80.842989] ata8.00: configured for UDMA/133

[   80.847660] ata8.00: Entering standby power mode

[   81.119426] xe 0000:03:00.0: [drm] GT0: suspended
[   81.800508] PM: suspend of devices complete after 1367.829 msecs
[   81.806661] PM: start suspend of devices complete after 1390.859 msecs
[   81.813244] PM: suspend devices took 1.398 seconds
[   81.820101] PM: late suspend of devices complete after 2.036 msecs

�[ 82.403857] serial 00:01: activated

[   82.489612] nvme nvme0: 16/0/0 default/read/poll queues
[   82.563318] r8169 0000:07:00.0 enp7s0: Link is Down
[   82.581444] xe REG[0x223a8-0x223af]: allow read access
[   82.586704] xe REG[0x1c03a8-0x1c03af]: allow read access
[   82.592071] xe REG[0x1d03a8-0x1d03af]: allow read access
[   82.597423] xe REG[0x1c83a8-0x1c83af]: allow read access
[   82.602765] xe REG[0x1d83a8-0x1d83af]: allow read access
[   82.608113] xe REG[0x1a3a8-0x1a3af]: allow read access
[   82.613281] xe REG[0x1c3a8-0x1c3af]: allow read access
[   82.618454] xe REG[0x1e3a8-0x1e3af]: allow read access
[   82.623634] xe REG[0x263a8-0x263af]: allow read access
[   82.628816] xe 0000:03:00.0: [drm] GT0: resumed
[   82.728005] ata7: SATA link down (SStatus 4 SControl 300)
[   82.733531] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[   82.739773] ata5.00: Entering active power mode
[   82.744398] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[   82.750618] ata6.00: Entering active power mode
[   82.755961] ata5.00: configured for UDMA/133
[   82.760479] ata5.00: Enabling discard_zeroes_data
[   82.836266] ata6.00: configured for UDMA/133
[   84.460081] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[   84.466354] ata8.00: Entering active power mode
[   84.497256] ata8.00: configured for UDMA/133

...

Quoted 69 lines · Rodrigo Vivi

Quoted 60 lines · Damien Le Moal

Quoted 36 lines · Rodrigo Vivi

Quoted 20 lines

Quoted 5 lines

So, maybe we have some kind of disks/configuration out there where this
start upon resume is needed? Maybe it is just a matter of timming to
ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive
to sleep and resume will reset the port (which should wake up the drive) and
then issue an IDENTIFY command (which will also wake up the drive) and other
read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and
likely port reset/drive gone events. So I think this is likely another subtle
race between scsi suspend and ata suspend that is causing a deadlock.

Quoted 15 lines

The main issue I think is that there is no direct ancestry between the ata port
(device) and scsi device, so the change to scsi async pm ops made a mess of the
suspend/resume operations ordering. For suspend, scsi device (child of ata port)
should be first, then ata port device (parent). For resume, the reverse order is
needed. PM normally ensures that parent/child ordering, but we lack that
parent/child relationship. I am working on fixing that but it is very slow
progress because I have been so far enable to recreate any of the issues that
have been reported. I am patching "blind"...

Quoted 5 lines

I believe your suspicious makes sense. And on these lines, that patch you
attached earlier would fix that. However my initial tries of that didn't
help. I'm going to run more tests and get back to you.

Rodrigo,

I pushed the resume-v2 branch to libata tree:

[email protected]:pub/scm/linux/kernel/git/dlemoal/libata (or
https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.gi
t)

This branch adds 13 patches on top of 6.5.0 to cleanup libata suspend/resume and
other device shutdown issues. The first 4 patches are the main ones to fix
suspend resume. I tested that on 2 different machines with different drives and
with qemu. All seems fine.

Quoted 3 lines

Could you try to run this through your CI ? I am very interested in seeing if it
survives your suspend/resume tests.

well, in the end this didn't affect the CI machinery as I was afraid.
it is only in my local DG2.

Quoted 7 lines

https://intel-gfx-ci.01.org/tree/intel-xe/bat-
all.html?testfilter=suspend
(bat-dg2-oem2 one)

I just got these 13 patches and applied to my branch and tested it again
and it still *fails* for me.

That is annoying... But I think the messages give us a hint as to what is going
on. See below.

Quoted 11 lines

[   79.648328] [IGT] kms_pipe_crc_basic: finished subtest pipe-A- DP-2, SUCCESS
[   79.657353] [IGT] kms_pipe_crc_basic: starting dynamic subtest pipe-B-DP-2
[   80.375042] PM: suspend entry (deep)
[   80.380799] Filesystems sync: 0.002 seconds
[   80.386476] Freezing user space processes
[   80.392286] Freezing user space processes completed (elapsed 0.001 seconds)
[   80.399294] OOM killer disabled.

Quoted 8 lines

[   80.402536] Freezing remaining freezable tasks [   80.408335] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[   80.439372] sd 5:0:0:0: [sdb] Synchronizing SCSI cache [   80.439716] serial 00:01: disabled
[   80.448011] sd 4:0:0:0: [sda] Synchronizing SCSI cache [   80.448014] sd 7:0:0:0: [sdc] Synchronizing SCSI cache [   80.453600] ata6.00: Entering standby power mode

This is sd 5:0:0:0. All good, ordered properly with the "Synchronizing SCSI cache".

Quoted 1 line

[   80.464217] ata5.00: Entering standby power mode

Same here for sd 4:0:0:0.

Quoted 4 lines

[   80.812294] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   80.818520] ata8.00: Entering active power mode
[   80.842989] ata8.00: configured for UDMA/133

Arg ! sd 7:0:0:0 is resuming ! But the above "Synchronizing SCSI cache" tells
us that it was suspending and libata EH did not yet put that drive to standby...

Quoted 1 line

[   80.847660] ata8.00: Entering standby power mode

... which happens here. So it looks like libata EH had both the suspend and
resume requests at the same time, which is totally weird.

Quoted 8 lines

[   81.119426] xe 0000:03:00.0: [drm] GT0: suspended
[   81.800508] PM: suspend of devices complete after 1367.829 msecs [   81.806661] PM: start suspend of devices complete after 1390.859 msecs
[   81.813244] PM: suspend devices took 1.398 seconds
[   81.820101] PM: late suspend of devices complete after 2.036 msecs

...and PM suspend completes here. Resume "starts" now (but clearly it started
earlier already given that sd 7:0:0:0 was reactivated.

Quoted 21 lines

�[   82.403857] serial 00:01: activated
[   82.489612] nvme nvme0: 16/0/0 default/read/poll queues [   82.563318] r8169 0000:07:00.0 enp7s0: Link is Down [   82.581444] xe REG[0x223a8-0x223af]: allow read access [   82.586704] xe REG[0x1c03a8-0x1c03af]: allow read access [   82.592071] xe REG[0x1d03a8-0x1d03af]: allow read access [   82.597423] xe REG[0x1c83a8-0x1c83af]: allow read access [   82.602765] xe REG[0x1d83a8-0x1d83af]: allow read access [   82.608113] xe REG[0x1a3a8-0x1a3af]: allow read access [   82.613281] xe REG[0x1c3a8-0x1c3af]: allow read access [   82.618454] xe REG[0x1e3a8-0x1e3af]: allow read access [   82.623634] xe REG[0x263a8-0x263af]: allow read access [   82.628816] xe 0000:03:00.0: [drm] GT0: resumed
[   82.728005] ata7: SATA link down (SStatus 4 SControl 300) [   82.733531] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   82.739773] ata5.00: Entering active power mode
[   82.744398] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   82.750618] ata6.00: Entering active power mode

Quoted 8 lines

[   82.755961] ata5.00: configured for UDMA/133
[   82.760479] ata5.00: Enabling discard_zeroes_data
[   82.836266] ata6.00: configured for UDMA/133
[   84.460081] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   84.466354] ata8.00: Entering active power mode
[   84.497256] ata8.00: configured for UDMA/133
...

And this looks all normal, the drives have all been transitioned to active
power mode as expected. And yet, your system is stuck after this, right ?

Can you try to boot with "sysrq_always_enabled" and try to see if sending
"ctrl-sysrq-t" keys can give you a stack backtrace of the tasks to see where
they are stuck ?

I am going to try something like you do with very short resume rtc timer and
multiple disks to see if I can reproduce. But it is starting to look like PM is
starting resuming before suspend completes...

Not sure that is correct. But the
end result may be that libata EH endup getting stuck. Let me dig further.

Quoted 119 lines · Damien Le Moal

Quoted 69 lines · Rodrigo Vivi

Quoted 60 lines · Damien Le Moal

Quoted 36 lines · Rodrigo Vivi

Quoted 20 lines

Quoted 5 lines

So, maybe we have some kind of disks/configuration out there where this
start upon resume is needed? Maybe it is just a matter of timming to
ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive
to sleep and resume will reset the port (which should wake up the drive) and
then issue an IDENTIFY command (which will also wake up the drive) and other
read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and
likely port reset/drive gone events. So I think this is likely another subtle
race between scsi suspend and ata suspend that is causing a deadlock.

Quoted 15 lines

The main issue I think is that there is no direct ancestry between the ata port
(device) and scsi device, so the change to scsi async pm ops made a mess of the
suspend/resume operations ordering. For suspend, scsi device (child of ata port)
should be first, then ata port device (parent). For resume, the reverse order is
needed. PM normally ensures that parent/child ordering, but we lack that
parent/child relationship. I am working on fixing that but it is very slow
progress because I have been so far enable to recreate any of the issues that
have been reported. I am patching "blind"...

Quoted 5 lines

I believe your suspicious makes sense. And on these lines, that patch you
attached earlier would fix that. However my initial tries of that didn't
help. I'm going to run more tests and get back to you.

Rodrigo,

I pushed the resume-v2 branch to libata tree:

[email protected]:pub/scm/linux/kernel/git/dlemoal/libata (or
https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.gi
t)

This branch adds 13 patches on top of 6.5.0 to cleanup libata suspend/resume and
other device shutdown issues. The first 4 patches are the main ones to fix
suspend resume. I tested that on 2 different machines with different drives and
with qemu. All seems fine.

Quoted 3 lines

Could you try to run this through your CI ? I am very interested in seeing if it
survives your suspend/resume tests.

well, in the end this didn't affect the CI machinery as I was afraid.
it is only in my local DG2.

Quoted 7 lines

https://intel-gfx-ci.01.org/tree/intel-xe/bat-
all.html?testfilter=suspend
(bat-dg2-oem2 one)

I just got these 13 patches and applied to my branch and tested it again
and it still *fails* for me.

That is annoying... But I think the messages give us a hint as to what is going
on. See below.

Quoted 11 lines

[   79.648328] [IGT] kms_pipe_crc_basic: finished subtest pipe-A- DP-2, SUCCESS
[   79.657353] [IGT] kms_pipe_crc_basic: starting dynamic subtest pipe-B-DP-2
[   80.375042] PM: suspend entry (deep)
[   80.380799] Filesystems sync: 0.002 seconds
[   80.386476] Freezing user space processes
[   80.392286] Freezing user space processes completed (elapsed 0.001 seconds)
[   80.399294] OOM killer disabled.

Quoted 8 lines

[   80.402536] Freezing remaining freezable tasks [   80.408335] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[   80.439372] sd 5:0:0:0: [sdb] Synchronizing SCSI cache [   80.439716] serial 00:01: disabled
[   80.448011] sd 4:0:0:0: [sda] Synchronizing SCSI cache [   80.448014] sd 7:0:0:0: [sdc] Synchronizing SCSI cache [   80.453600] ata6.00: Entering standby power mode

This is sd 5:0:0:0. All good, ordered properly with the "Synchronizing SCSI cache".

Quoted 1 line

[   80.464217] ata5.00: Entering standby power mode

Same here for sd 4:0:0:0.

Quoted 4 lines

[   80.812294] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   80.818520] ata8.00: Entering active power mode
[   80.842989] ata8.00: configured for UDMA/133

Arg ! sd 7:0:0:0 is resuming ! But the above "Synchronizing SCSI cache" tells
us that it was suspending and libata EH did not yet put that drive to standby...

Quoted 5 lines

Quoted 1 line

[   80.847660] ata8.00: Entering standby power mode

... which happens here. So it looks like libata EH had both the suspend and
resume requests at the same time, which is totally weird.

although it looks weird, it totally matches the 'use case'. I mean, if I suspend, resume, and wait a bit before suspend and resume again, it will work 100% of the time.
The issue is really only when another suspend comes right after the resume, in a loop without any wait.

Quoted 9 lines

Quoted 8 lines

[   81.119426] xe 0000:03:00.0: [drm] GT0: suspended
[   81.800508] PM: suspend of devices complete after 1367.829 msecs [   81.806661] PM: start suspend of devices complete after 1390.859 msecs
[   81.813244] PM: suspend devices took 1.398 seconds
[   81.820101] PM: late suspend of devices complete after 2.036 msecs

Quoted 3 lines

...and PM suspend completes here. Resume "starts" now (but clearly it started
earlier already given that sd 7:0:0:0 was reactivated.

that is weird.

Quoted 30 lines

Quoted 21 lines

�[   82.403857] serial 00:01: activated
[   82.489612] nvme nvme0: 16/0/0 default/read/poll queues [   82.563318] r8169 0000:07:00.0 enp7s0: Link is Down [   82.581444] xe REG[0x223a8-0x223af]: allow read access [   82.586704] xe REG[0x1c03a8-0x1c03af]: allow read access [   82.592071] xe REG[0x1d03a8-0x1d03af]: allow read access [   82.597423] xe REG[0x1c83a8-0x1c83af]: allow read access [   82.602765] xe REG[0x1d83a8-0x1d83af]: allow read access [   82.608113] xe REG[0x1a3a8-0x1a3af]: allow read access [   82.613281] xe REG[0x1c3a8-0x1c3af]: allow read access [   82.618454] xe REG[0x1e3a8-0x1e3af]: allow read access [   82.623634] xe REG[0x263a8-0x263af]: allow read access [   82.628816] xe 0000:03:00.0: [drm] GT0: resumed
[   82.728005] ata7: SATA link down (SStatus 4 SControl 300) [   82.733531] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   82.739773] ata5.00: Entering active power mode
[   82.744398] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   82.750618] ata6.00: Entering active power mode

Quoted 8 lines

[   82.755961] ata5.00: configured for UDMA/133
[   82.760479] ata5.00: Enabling discard_zeroes_data
[   82.836266] ata6.00: configured for UDMA/133
[   84.460081] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   84.466354] ata8.00: Entering active power mode
[   84.497256] ata8.00: configured for UDMA/133
...

Quoted 4 lines

And this looks all normal, the drives have all been transitioned to active
power mode as expected. And yet, your system is stuck after this, right ?

yes

Quoted 5 lines

Can you try to boot with "sysrq_always_enabled" and try to see if sending
"ctrl-sysrq-t" keys can give you a stack backtrace of the tasks to see where
they are stuck ?

I will try tomorrow.

Quoted 7 lines

I am going to try something like you do with very short resume rtc timer and
multiple disks to see if I can reproduce. But it is starting to look like PM is
starting resuming before suspend completes...

yes, this is what it looks like.

Quoted 119 lines · Damien Le Moal

Quoted 69 lines · Rodrigo Vivi

Quoted 60 lines · Damien Le Moal

Quoted 36 lines · Rodrigo Vivi

Quoted 20 lines

Quoted 5 lines

So, maybe we have some kind of disks/configuration out there where this
start upon resume is needed? Maybe it is just a matter of timming to
ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive
to sleep and resume will reset the port (which should wake up the drive) and
then issue an IDENTIFY command (which will also wake up the drive) and other
read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and
likely port reset/drive gone events. So I think this is likely another subtle
race between scsi suspend and ata suspend that is causing a deadlock.

Quoted 15 lines

The main issue I think is that there is no direct ancestry between the ata port
(device) and scsi device, so the change to scsi async pm ops made a mess of the
suspend/resume operations ordering. For suspend, scsi device (child of ata port)
should be first, then ata port device (parent). For resume, the reverse order is
needed. PM normally ensures that parent/child ordering, but we lack that
parent/child relationship. I am working on fixing that but it is very slow
progress because I have been so far enable to recreate any of the issues that
have been reported. I am patching "blind"...

Quoted 5 lines

I believe your suspicious makes sense. And on these lines, that patch you
attached earlier would fix that. However my initial tries of that didn't
help. I'm going to run more tests and get back to you.

Rodrigo,

I pushed the resume-v2 branch to libata tree:

[email protected]:pub/scm/linux/kernel/git/dlemoal/libata (or
https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.gi
t)

This branch adds 13 patches on top of 6.5.0 to cleanup libata suspend/resume and
other device shutdown issues. The first 4 patches are the main ones to fix
suspend resume. I tested that on 2 different machines with different drives and
with qemu. All seems fine.

Quoted 3 lines

Could you try to run this through your CI ? I am very interested in seeing if it
survives your suspend/resume tests.

well, in the end this didn't affect the CI machinery as I was afraid.
it is only in my local DG2.

Quoted 7 lines

https://intel-gfx-ci.01.org/tree/intel-xe/bat-
all.html?testfilter=suspend
(bat-dg2-oem2 one)

I just got these 13 patches and applied to my branch and tested it again
and it still *fails* for me.

That is annoying... But I think the messages give us a hint as to what is going
on. See below.

Quoted 11 lines

[   79.648328] [IGT] kms_pipe_crc_basic: finished subtest pipe-A- DP-2, SUCCESS
[   79.657353] [IGT] kms_pipe_crc_basic: starting dynamic subtest pipe-B-DP-2
[   80.375042] PM: suspend entry (deep)
[   80.380799] Filesystems sync: 0.002 seconds
[   80.386476] Freezing user space processes
[   80.392286] Freezing user space processes completed (elapsed 0.001 seconds)
[   80.399294] OOM killer disabled.

Quoted 8 lines

[   80.402536] Freezing remaining freezable tasks [   80.408335] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[   80.439372] sd 5:0:0:0: [sdb] Synchronizing SCSI cache [   80.439716] serial 00:01: disabled
[   80.448011] sd 4:0:0:0: [sda] Synchronizing SCSI cache [   80.448014] sd 7:0:0:0: [sdc] Synchronizing SCSI cache [   80.453600] ata6.00: Entering standby power mode

This is sd 5:0:0:0. All good, ordered properly with the "Synchronizing SCSI cache".

Quoted 1 line

[   80.464217] ata5.00: Entering standby power mode

Same here for sd 4:0:0:0.

Quoted 4 lines

[   80.812294] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   80.818520] ata8.00: Entering active power mode
[   80.842989] ata8.00: configured for UDMA/133

Arg ! sd 7:0:0:0 is resuming ! But the above "Synchronizing SCSI cache" tells
us that it was suspending and libata EH did not yet put that drive to standby...

Quoted 5 lines

Quoted 1 line

[   80.847660] ata8.00: Entering standby power mode

... which happens here. So it looks like libata EH had both the suspend and
resume requests at the same time, which is totally weird.

although it looks weird, it totally matches the 'use case'. I mean, if I suspend, resume, and wait a bit before suspend and resume again, it will work 100% of the time.
The issue is really only when another suspend comes right after the resume, in a loop without any wait.

Quoted 9 lines

Quoted 8 lines

[   81.119426] xe 0000:03:00.0: [drm] GT0: suspended
[   81.800508] PM: suspend of devices complete after 1367.829 msecs [   81.806661] PM: start suspend of devices complete after 1390.859 msecs
[   81.813244] PM: suspend devices took 1.398 seconds
[   81.820101] PM: late suspend of devices complete after 2.036 msecs

Quoted 3 lines

...and PM suspend completes here. Resume "starts" now (but clearly it started
earlier already given that sd 7:0:0:0 was reactivated.

that is weird.

Quoted 30 lines

Quoted 29 lines

�[   82.403857] serial 00:01: activated
[   82.489612] nvme nvme0: 16/0/0 default/read/poll queues [   82.563318] r8169 0000:07:00.0 enp7s0: Link is Down [   82.581444] xe REG[0x223a8-0x223af]: allow read access [   82.586704] xe REG[0x1c03a8-0x1c03af]: allow read access [   82.592071] xe REG[0x1d03a8-0x1d03af]: allow read access [   82.597423] xe REG[0x1c83a8-0x1c83af]: allow read access [   82.602765] xe REG[0x1d83a8-0x1d83af]: allow read access [   82.608113] xe REG[0x1a3a8-0x1a3af]: allow read access [   82.613281] xe REG[0x1c3a8-0x1c3af]: allow read access [   82.618454] xe REG[0x1e3a8-0x1e3af]: allow read access [   82.623634] xe REG[0x263a8-0x263af]: allow read access [   82.628816] xe 0000:03:00.0: [drm] GT0: resumed
[   82.728005] ata7: SATA link down (SStatus 4 SControl 300) [   82.733531] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   82.739773] ata5.00: Entering active power mode
[   82.744398] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   82.750618] ata6.00: Entering active power mode
[   82.755961] ata5.00: configured for UDMA/133
[   82.760479] ata5.00: Enabling discard_zeroes_data
[   82.836266] ata6.00: configured for UDMA/133
[   84.460081] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   84.466354] ata8.00: Entering active power mode
[   84.497256] ata8.00: configured for UDMA/133
...

Quoted 4 lines

And this looks all normal, the drives have all been transitioned to active
power mode as expected. And yet, your system is stuck after this, right ?

yes

Quoted 177 lines · Rodrigo

Quoted 119 lines · Damien Le Moal

Quoted 69 lines · Rodrigo Vivi

Quoted 60 lines · Damien Le Moal

Quoted 36 lines · Rodrigo Vivi

Quoted 20 lines

Quoted 5 lines

So, maybe we have some kind of disks/configuration out there where this
start upon resume is needed? Maybe it is just a matter of timming to
ensure some firmware underneath is up and back to life?

I do not think so. Suspend will issue a start stop unit command to put the drive
to sleep and resume will reset the port (which should wake up the drive) and
then issue an IDENTIFY command (which will also wake up the drive) and other
read logs etc to rescan the drive.
In both cases, if the commands do not complete, we would see errors/timeout and
likely port reset/drive gone events. So I think this is likely another subtle
race between scsi suspend and ata suspend that is causing a deadlock.

Quoted 15 lines

The main issue I think is that there is no direct ancestry between the ata port
(device) and scsi device, so the change to scsi async pm ops made a mess of the
suspend/resume operations ordering. For suspend, scsi device (child of ata port)
should be first, then ata port device (parent). For resume, the reverse order is
needed. PM normally ensures that parent/child ordering, but we lack that
parent/child relationship. I am working on fixing that but it is very slow
progress because I have been so far enable to recreate any of the issues that
have been reported. I am patching "blind"...

Quoted 5 lines

I believe your suspicious makes sense. And on these lines, that patch you
attached earlier would fix that. However my initial tries of that didn't
help. I'm going to run more tests and get back to you.

Rodrigo,

I pushed the resume-v2 branch to libata tree:

[email protected]:pub/scm/linux/kernel/git/dlemoal/libata (or
https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.gi
t)

This branch adds 13 patches on top of 6.5.0 to cleanup libata suspend/resume and
other device shutdown issues. The first 4 patches are the main ones to fix
suspend resume. I tested that on 2 different machines with different drives and
with qemu. All seems fine.

Quoted 3 lines

Could you try to run this through your CI ? I am very interested in seeing if it
survives your suspend/resume tests.

well, in the end this didn't affect the CI machinery as I was afraid.
it is only in my local DG2.

Quoted 7 lines

https://intel-gfx-ci.01.org/tree/intel-xe/bat-
all.html?testfilter=suspend
(bat-dg2-oem2 one)

I just got these 13 patches and applied to my branch and tested it again
and it still *fails* for me.

That is annoying... But I think the messages give us a hint as to what is going
on. See below.

Quoted 11 lines

[   79.648328] [IGT] kms_pipe_crc_basic: finished subtest pipe-A- DP-2, SUCCESS
[   79.657353] [IGT] kms_pipe_crc_basic: starting dynamic subtest pipe-B-DP-2
[   80.375042] PM: suspend entry (deep)
[   80.380799] Filesystems sync: 0.002 seconds
[   80.386476] Freezing user space processes
[   80.392286] Freezing user space processes completed (elapsed 0.001 seconds)
[   80.399294] OOM killer disabled.

Quoted 8 lines

[   80.402536] Freezing remaining freezable tasks [   80.408335] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[   80.439372] sd 5:0:0:0: [sdb] Synchronizing SCSI cache [   80.439716] serial 00:01: disabled
[   80.448011] sd 4:0:0:0: [sda] Synchronizing SCSI cache [   80.448014] sd 7:0:0:0: [sdc] Synchronizing SCSI cache [   80.453600] ata6.00: Entering standby power mode

This is sd 5:0:0:0. All good, ordered properly with the "Synchronizing SCSI cache".

Quoted 1 line

[   80.464217] ata5.00: Entering standby power mode

Same here for sd 4:0:0:0.

Quoted 4 lines

[   80.812294] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   80.818520] ata8.00: Entering active power mode
[   80.842989] ata8.00: configured for UDMA/133

Arg ! sd 7:0:0:0 is resuming ! But the above "Synchronizing SCSI cache" tells
us that it was suspending and libata EH did not yet put that drive to standby...

Quoted 5 lines

Quoted 1 line

[   80.847660] ata8.00: Entering standby power mode

... which happens here. So it looks like libata EH had both the suspend and
resume requests at the same time, which is totally weird.

although it looks weird, it totally matches the 'use case'. I mean, if I suspend, resume, and wait a bit before suspend and resume again, it will work 100% of the time.
The issue is really only when another suspend comes right after the resume, in a loop without any wait.

Quoted 9 lines

Quoted 8 lines

[   81.119426] xe 0000:03:00.0: [drm] GT0: suspended
[   81.800508] PM: suspend of devices complete after 1367.829 msecs [   81.806661] PM: start suspend of devices complete after 1390.859 msecs
[   81.813244] PM: suspend devices took 1.398 seconds
[   81.820101] PM: late suspend of devices complete after 2.036 msecs

Quoted 3 lines

...and PM suspend completes here. Resume "starts" now (but clearly it started
earlier already given that sd 7:0:0:0 was reactivated.

that is weird.

Quoted 30 lines

Quoted 29 lines

�[   82.403857] serial 00:01: activated
[   82.489612] nvme nvme0: 16/0/0 default/read/poll queues [   82.563318] r8169 0000:07:00.0 enp7s0: Link is Down [   82.581444] xe REG[0x223a8-0x223af]: allow read access [   82.586704] xe REG[0x1c03a8-0x1c03af]: allow read access [   82.592071] xe REG[0x1d03a8-0x1d03af]: allow read access [   82.597423] xe REG[0x1c83a8-0x1c83af]: allow read access [   82.602765] xe REG[0x1d83a8-0x1d83af]: allow read access [   82.608113] xe REG[0x1a3a8-0x1a3af]: allow read access [   82.613281] xe REG[0x1c3a8-0x1c3af]: allow read access [   82.618454] xe REG[0x1e3a8-0x1e3af]: allow read access [   82.623634] xe REG[0x263a8-0x263af]: allow read access [   82.628816] xe 0000:03:00.0: [drm] GT0: resumed
[   82.728005] ata7: SATA link down (SStatus 4 SControl 300) [   82.733531] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   82.739773] ata5.00: Entering active power mode
[   82.744398] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   82.750618] ata6.00: Entering active power mode
[   82.755961] ata5.00: configured for UDMA/133
[   82.760479] ata5.00: Enabling discard_zeroes_data
[   82.836266] ata6.00: configured for UDMA/133
[   84.460081] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl
300)
[   84.466354] ata8.00: Entering active power mode
[   84.497256] ata8.00: configured for UDMA/133
...

Quoted 6 lines

Quoted 4 lines

And this looks all normal, the drives have all been transitioned to active
power mode as expected. And yet, your system is stuck after this, right ?

yes

I think I have now figured it out, and fixed. I could reliably recreate the same hang both with qemu using a failed suspend (using a device not supporting suspend) and real hardware with a short rtc wake.

It turns out that the root cause of the hang is ata_scsi_dev_rescan(), which is scheduled asynchronously from PM context on resume. With quick suspend after a resume, suspend may win the race against that ata_scsi_dev_rescan() task execution and we endup calling scsi_rescan_device() on a suspended device, causing that function to wait with the device_lock() held, which causes PM to deadlock when it needs to resume the scsi device. The recent commit 6aa0365a3c85 ("ata: libata-scsi: Avoid deadlock on rescan after device resume") was intended to fix that, but it did so less than ideally and the fix has a race on the scsi power state check, thus not always preventing the resume hang.

I pushed a new patch series that goes on top of 6.5.0: resume-v3 branch in the libata tree:

https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.git

This works very well for me. Using this script on real hardware:

for (( i=0; i<20; i++ )); do

	echo "+2" > /sys/class/rtc/rtc0/wakealarm
	echo mem > /sys/power/state

done

The system repeatedly suspends and resumes and comes back OK. Of note is that if I set the delay to +1 second, then I sometime do not see the system resume and the script stops. But using wakeup-on-lan (wol command) from another machine to wake it up, the machine resumes normally and continues executing the script. So it seems that setting the rtc alarm unreasonably early result in it being lost and the system suspending wating to be woken up.

I also tested this in qemu. As mentioned before, I cannot get rtc alarm to wake up the VM guest though. However, using a virtio device that does not support suspend, resume strats in the middle of the suspend operation due to the suspend error reported by that device. And it turns out that systemd really insists on suspending the system despite the error, so when running "systemctl suspend" I see a retry for suspend right after the first failed one. That is enough to trigger the issue without the patches.

Please test !

Thanks.

Signature · 2 lines

Damien Le Moal
Western Digital Research

Quoted 41 lines

I think I have now figured it out, and fixed. I could reliably recreate the same hang both with qemu using a failed suspend (using a device not supporting suspend) and real hardware with a short rtc wake.

It turns out that the root cause of the hang is ata_scsi_dev_rescan(), which is scheduled asynchronously from PM context on resume. With quick suspend after a resume, suspend may win the race against that ata_scsi_dev_rescan() task execution and we endup calling scsi_rescan_device() on a suspended device, causing that function to wait with the device_lock() held, which causes PM to deadlock when it needs to resume the scsi device. The recent commit 6aa0365a3c85 ("ata: libata-scsi: Avoid deadlock on rescan after device resume") was intended to fix that, but it did so less than ideally and the fix has a race on the scsi power state check, thus not always preventing the resume hang.

I pushed a new patch series that goes on top of 6.5.0: resume-v3 branch in the libata tree:

https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.git

This works very well for me. Using this script on real hardware:

for (( i=0; i<20; i++ )); do

	echo "+2" > /sys/class/rtc/rtc0/wakealarm
	echo mem > /sys/power/state

done

The system repeatedly suspends and resumes and comes back OK. Of note is that if I set the delay to +1 second, then I sometime do not see the system resume and the script stops. But using wakeup-on-lan (wol command) from another machine to wake it up, the machine resumes normally and continues executing the script. So it seems that setting the rtc alarm unreasonably early result in it being lost and the system suspending wating to be woken up.

I also tested this in qemu. As mentioned before, I cannot get rtc alarm to wake up the VM guest though. However, using a virtio device that does not support suspend, resume strats in the middle of the suspend operation due to the suspend error reported by that device. And it turns out that systemd really insists on suspending the system despite the error, so when running "systemctl suspend" I see a retry for suspend right after the first failed one. That is enough to trigger the issue without the patches.

Quoted 1 line

Please test !

\o/ works for me!

Feel free to use:

Tested-by Rodrigo Vivi <[email protected]>

I have the CONFIG_PM_DEBUG here with no_console_suspend.
If you remember any other config or parameter that would help, please let me know that I collect it again:

[  104.571459] PM: suspend entry (deep)
[  104.585967] Filesystems sync: 0.010 seconds
[  104.618685] Freezing user space processes
[  104.625374] Freezing user space processes completed (elapsed 0.002 seconds)
[  104.632448] OOM killer disabled.
[  104.635712] Freezing remaining freezable tasks
[  104.641899] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)

[  104.669767] wlp6s0: deauthenticating from 08:36:c9:85:df:ef by local choice (Reason: 3=DEAUTH_LEAVING)
[  104.679812] serial 00:01: disabled
[  104.683466] sd 7:0:0:0: [sdc] Synchronizing SCSI cache
[  104.688902] sd 7:0:0:0: [sdc] Stopping disk
[  104.693176] sd 5:0:0:0: [sdb] Synchronizing SCSI cache
[  104.698419] sd 4:0:0:0: [sda] Synchronizing SCSI cache
[  104.703730] sd 4:0:0:0: [sda] Stopping disk
[  104.885912] sd 5:0:0:0: [sdb] Stopping disk
[  106.163215] PM: suspend devices took 1.514 seconds

[  107.003217] serial 00:01: activated
[  107.076779] nvme nvme0: 16/0/0 default/read/poll queues
[  107.123917] r8169 0000:07:00.0 enp7s0: Link is Down
[  107.208945] PM: resume devices took 0.241 seconds
[  107.214746] pcieport 0000:00:1c.0: PCI bridge to [bus 06]
[  107.220274] pcieport 0000:00:1c.0:   bridge window [mem 0x43700000-0x437fffff]
[  107.227538] OOM killer enabled.
[  107.230710] Restarting tasks ...

[  107.231803] pcieport 0000:00:1c.2: PCI bridge to [bus 07]
[  107.236474] done.
[  107.240599] pcieport 0000:00:1c.2:   bridge window [io  0x4000-0x4fff]
[  107.242574] random: crng reseeded on system resumption
[  107.249119] pcieport 0000:00:1c.2:   bridge window [mem 0x43600000-0x436fffff]
[  107.249405] pcieport 0000:00:1c.6: PCI bridge to [bus 08]
[  107.259714] PM: suspend exit
[  107.261623] pcieport 0000:00:1c.6:   bridge window [io  0x3000-0x3fff]

[  107.276554] pcieport 0000:00:1c.6:   bridge window [mem 0x43500000-0x435fffff]
[  107.283849] pcieport 0000:00:1c.6:   bridge window [mem 0x70900000-0x709fffff 64bit pref]
[  107.293567] ata7: SATA link down (SStatus 4 SControl 300)
[  107.304150] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  107.310975] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  107.319173] ata5.00: configured for UDMA/133
[  107.324620] ata5.00: Enabling discard_zeroes_data
[  107.398370] ata6.00: configured for UDMA/133

[  108.563229] PM: suspend entry (deep)
[  108.573610] Filesystems sync: 0.006 seconds
[  108.580617] Freezing user space processes
[  108.586774] Freezing user space processes completed (elapsed 0.002 seconds)
[  108.593793] OOM killer disabled.
[  108.597055] Freezing remaining freezable tasks
[  108.603246] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)

[  108.621515] sd 7:0:0:0: [sdc] Synchronizing SCSI cache
[  108.621522] sd 5:0:0:0: [sdb] Synchronizing SCSI cache
[  108.622018] serial 00:01: disabled
[  108.635420] sd 4:0:0:0: [sda] Synchronizing SCSI cache
[  108.640747] sd 4:0:0:0: [sda] Stopping disk
[  108.644148] sd 5:0:0:0: [sdb] Stopping disk
[  108.983487] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  108.991923] ata8.00: configured for UDMA/133
[  108.996423] sd 7:0:0:0: [sdc] Stopping disk
[  109.973722] PM: suspend devices took 1.363 seconds

[  110.721600] serial 00:01: activated
[  110.802094] nvme nvme0: 16/0/0 default/read/poll queues
[  110.873036] r8169 0000:07:00.0 enp7s0: Link is Down
[  111.032278] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  111.038583] ata7: SATA link down (SStatus 4 SControl 300)
[  111.044065] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  111.051326] ata5.00: configured for UDMA/133
[  111.056118] ata5.00: Enabling discard_zeroes_data
[  111.131795] ata6.00: configured for UDMA/133
[  112.713764] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  112.724250] ata8.00: configured for UDMA/133

Quoted 30 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Quoted 6 lines

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Hi Damien,

Last week I noticed that a basic test in our validation started failing, then I noticed that it was subsequent quick suspend and autoresume using rtcwake that was problematic.

I couldn't collect any specific log that was pointing to some useful direction. After a painful bisect I got to this patch. After reverting in from the top of our tree, the tests are back to life.

The issue was that the subsequent quick suspend-resume (sometimes the second, sometimes third or even sixth) was simply hanging the machine in different points at Suspend.

So, maybe we have some kind of disks/configuration out there where this start upon resume is needed? Maybe it is just a matter of timming to ensure some firmware underneath is up and back to life?

Well, please let me know the best way to report this issue to you and what kind of logs I should get.

Meanwhile if this ends up blocking our CI we can keep a revert in a topic branch for CI.

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

Hi Damien,

Quoted 37 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Quoted 4 lines

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

Thanks for your patch, which is now commit 0a8589055936d8fe ("ata,scsi: do not issue START STOP UNIT on resume") in v6.5-rc5. Sorry for being late to the party, but this commit landed upstream during my summer holidays, and apparently I wasn't that focussed on noticing small behavioral changes after getting back to work...

I noticed an oddity after s2idle or s2ram on Renesas Salvator-XS (R-Car H3 ES2.0) with an old (spinning rust) SATA drive, and bisected it to this commit: when accessing the drive after system resume, there is now a delay of ca. 5s before data is returned, presumably due to starting the drive, and having to wait for it to spin up to be able to read data. But the good news is that the actual system resume takes less time than before (reduced by even more than ca. 5s!), so this looks like a net win...

I'm not sure this is to be called a regression, I just wanted you to be aware of it.

Quoted 49 lines · Geert Uytterhoeven

Quoted 37 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Quoted 4 lines

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

Thanks for your patch, which is now commit 0a8589055936d8fe ("ata,scsi: do not issue START STOP UNIT on resume") in v6.5-rc5. Sorry for being late to the party, but this commit landed upstream during my summer holidays, and apparently I wasn't that focussed on noticing small behavioral changes after getting back to work...

Quoted 8 lines

I noticed an oddity after s2idle or s2ram on Renesas Salvator-XS (R-Car H3 ES2.0) with an old (spinning rust) SATA drive, and bisected it to this commit: when accessing the drive after system resume, there is now a delay of ca. 5s before data is returned, presumably due to starting the drive, and having to wait for it to spin up to be able to read data. But the good news is that the actual system resume takes less time than before (reduced by even more than ca. 5s!), so this looks like a net win...

Thanks for the report. The delay for the first data access from user space right after resume is 100% expected, with or without this patch. The reason is that waking up the drive (spinning it up) is done asynchronously from the PM resume context, so when you get "PM suspend exit" message signaling that the system is resumed, the drive may not yet be spinning. Any access will wait for that to happen before proceeding. Depending on the drive that can take up to 10s or so.

I am not entirely sure where the net win you see come from. But the patch you mention is in fact completely wrong and does not fix the underlying issues with ata suspend/resume and potential deadlocks in PM due to ata ports relationship with scsi devices. So I have been working on fixing this for the last 2 weeks, after another user also reported issues with the patch you mention [1].

Could you try libata for-next branch on your system ? There are 7 fix patches in there that I plan to send out for 6.6-rc2 to fix the patch in question and other issues potentially causing deadlocks on resume. The patches were posted also [2].

https://lore.kernel.org/linux-ide/[email protected]/T/#t

Quoted 59 lines · Damien Le Moal

Quoted 49 lines · Geert Uytterhoeven

Quoted 37 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Quoted 4 lines

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

Thanks for your patch, which is now commit 0a8589055936d8fe ("ata,scsi: do not issue START STOP UNIT on resume") in v6.5-rc5. Sorry for being late to the party, but this commit landed upstream during my summer holidays, and apparently I wasn't that focussed on noticing small behavioral changes after getting back to work...

Quoted 8 lines

I noticed an oddity after s2idle or s2ram on Renesas Salvator-XS (R-Car H3 ES2.0) with an old (spinning rust) SATA drive, and bisected it to this commit: when accessing the drive after system resume, there is now a delay of ca. 5s before data is returned, presumably due to starting the drive, and having to wait for it to spin up to be able to read data. But the good news is that the actual system resume takes less time than before (reduced by even more than ca. 5s!), so this looks like a net win...

Quoted 6 lines

Thanks for the report. The delay for the first data access from user space right after resume is 100% expected, with or without this patch. The reason is that waking up the drive (spinning it up) is done asynchronously from the PM resume context, so when you get "PM suspend exit" message signaling that the system is resumed, the drive may not yet be spinning. Any access will wait for that to happen before proceeding. Depending on the drive that can take up to 10s or so.

That does not match with what I am seeing: before this patch, there was no delay on first data access from user space, as the drive is fully spun up when system resume returns.
With this patch, system resume returns earlier, and the drive is only spun up when user space starts accessing data.

Note that I do not have any file system mounted, and use "hd /dev/sda | head -70" to access the disk.

Quoted 6 lines

I am not entirely sure where the net win you see come from. But the patch you mention is in fact completely wrong and does not fix the underlying issues with ata suspend/resume and potential deadlocks in PM due to ata ports relationship with scsi devices. So I have been working on fixing this for the last 2 weeks, after another user also reported issues with the patch you mention [1].

Quoted 5 lines

Could you try libata for-next branch on your system ? There are 7 fix patches in there that I plan to send out for 6.6-rc2 to fix the patch in question and other issues potentially causing deadlocks on resume. The patches were posted also [2].

https://lore.kernel.org/linux-ide/[email protected]/T/#t

Unfortunately that didn't work, as /dev/sda no longer exists. Will reply to the patch I bisected the issue to...

Hi Damien,

Quoted 88 lines · Geert Uytterhoeven

Quoted 59 lines · Damien Le Moal

Quoted 49 lines · Geert Uytterhoeven

Quoted 37 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Quoted 4 lines

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

Thanks for your patch, which is now commit 0a8589055936d8fe ("ata,scsi: do not issue START STOP UNIT on resume") in v6.5-rc5. Sorry for being late to the party, but this commit landed upstream during my summer holidays, and apparently I wasn't that focussed on noticing small behavioral changes after getting back to work...

Quoted 8 lines

I noticed an oddity after s2idle or s2ram on Renesas Salvator-XS (R-Car H3 ES2.0) with an old (spinning rust) SATA drive, and bisected it to this commit: when accessing the drive after system resume, there is now a delay of ca. 5s before data is returned, presumably due to starting the drive, and having to wait for it to spin up to be able to read data. But the good news is that the actual system resume takes less time than before (reduced by even more than ca. 5s!), so this looks like a net win...

Quoted 6 lines

Thanks for the report. The delay for the first data access from user space right after resume is 100% expected, with or without this patch. The reason is that waking up the drive (spinning it up) is done asynchronously from the PM resume context, so when you get "PM suspend exit" message signaling that the system is resumed, the drive may not yet be spinning. Any access will wait for that to happen before proceeding. Depending on the drive that can take up to 10s or so.

That does not match with what I am seeing: before this patch, there was no delay on first data access from user space, as the drive is fully spun up when system resume returns.
With this patch, system resume returns earlier, and the drive is only spun up when user space starts accessing data.

Note that I do not have any file system mounted, and use "hd /dev/sda | head -70" to access the disk.

Quoted 11 lines

I am not entirely sure where the net win you see come from. But the patch you mention is in fact completely wrong and does not fix the underlying issues with ata suspend/resume and potential deadlocks in PM due to ata ports relationship with scsi devices. So I have been working on fixing this for the last 2 weeks, after another user also reported issues with the patch you mention [1].

Could you try libata for-next branch on your system ? There are 7 fix patches in there that I plan to send out for 6.6-rc2 to fix the patch in question and other issues potentially causing deadlocks on resume. The patches were posted also [2].

https://lore.kernel.org/linux-ide/[email protected]/T/#t

Quoted 2 lines

Unfortunately that didn't work, as /dev/sda no longer exists. Will reply to the patch I bisected the issue to...

With libata/for-next (fa2259a59966c005 ("ata: libata: Cleanup inline DMA helper functions")) and commit 99626085d036ec32 ("ata: libata-scsi:
link ata port and scsi device") reverted, it behaves as before (disk is spun up when system resume completes, no delay when accessing the disk from userspace).

Quoted 90 lines · Geert Uytterhoeven

Quoted 88 lines · Geert Uytterhoeven

Quoted 59 lines · Damien Le Moal

Quoted 49 lines · Geert Uytterhoeven

Quoted 37 lines · Damien Le Moal

During system resume, ata_port_pm_resume() triggers ata EH to
1) Resume the controller
2) Reset and rescan the ports
3) Revalidate devices
This EH execution is started asynchronously from ata_port_pm_resume(), which means that when sd_resume() is executed, none or only part of the above processing may have been executed. However, sd_resume() issues a START STOP UNIT to wake up the drive from sleep mode. This command is translated to ATA with ata_scsi_start_stop_xlat() and issued to the device. However, depending on the state of execution of the EH process and revalidation triggerred by ata_port_pm_resume(), two things may happen:
1) The START STOP UNIT fails if it is received before the controller has been reenabled at the beginning of the EH execution. This is visible with error messages like:

ata10.00: device reported invalid CHS sector 0
sd 9:0:0:0: [sdc] Start/Stop Unit failed: Result: hostbyte=DID_OK driverbyte=DRIVER_OK sd 9:0:0:0: [sdc] Sense Key : Illegal Request [current]
sd 9:0:0:0: [sdc] Add. Sense: Unaligned write command
sd 9:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 returns -5 sd 9:0:0:0: PM: failed to resume async: error -5

2) The START STOP UNIT command is received while the EH process is on-going, which mean that it is stopped and must wait for its completion, at which point the command is rather useless as the drive is already fully spun up already. This case results also in a significant delay in sd_resume() which is observable by users as the entire system resume completion is delayed.

Given that ATA devices will be woken up by libata activity on resume, sd_resume() has no need to issue a START STOP UNIT command, which solves the above mentioned problems. Do not issue this command by introducing the new scsi_device flag no_start_on_resume and setting this flag to 1 in ata_scsi_dev_config(). sd_resume() is modified to issue a START STOP UNIT command only if this flag is not set.

Quoted 4 lines

Reported-by Paul Ausbeck <[email protected]>

Closes https://bugzilla.kernel.org/show_bug.cgi?id=215880

Fixes a19a93e4c6a9 ("scsi: core: pm: Rely on the device driver core for async power management")

Signed-off-by Damien Le Moal <[email protected]>

Thanks for your patch, which is now commit 0a8589055936d8fe ("ata,scsi: do not issue START STOP UNIT on resume") in v6.5-rc5. Sorry for being late to the party, but this commit landed upstream during my summer holidays, and apparently I wasn't that focussed on noticing small behavioral changes after getting back to work...

Quoted 8 lines

I noticed an oddity after s2idle or s2ram on Renesas Salvator-XS (R-Car H3 ES2.0) with an old (spinning rust) SATA drive, and bisected it to this commit: when accessing the drive after system resume, there is now a delay of ca. 5s before data is returned, presumably due to starting the drive, and having to wait for it to spin up to be able to read data. But the good news is that the actual system resume takes less time than before (reduced by even more than ca. 5s!), so this looks like a net win...

Quoted 6 lines

Thanks for the report. The delay for the first data access from user space right after resume is 100% expected, with or without this patch. The reason is that waking up the drive (spinning it up) is done asynchronously from the PM resume context, so when you get "PM suspend exit" message signaling that the system is resumed, the drive may not yet be spinning. Any access will wait for that to happen before proceeding. Depending on the drive that can take up to 10s or so.

That does not match with what I am seeing: before this patch, there was no delay on first data access from user space, as the drive is fully spun up when system resume returns.
With this patch, system resume returns earlier, and the drive is only spun up when user space starts accessing data.

Note that I do not have any file system mounted, and use "hd /dev/sda | head -70" to access the disk.

Quoted 11 lines

I am not entirely sure where the net win you see come from. But the patch you mention is in fact completely wrong and does not fix the underlying issues with ata suspend/resume and potential deadlocks in PM due to ata ports relationship with scsi devices. So I have been working on fixing this for the last 2 weeks, after another user also reported issues with the patch you mention [1].

Could you try libata for-next branch on your system ? There are 7 fix patches in there that I plan to send out for 6.6-rc2 to fix the patch in question and other issues potentially causing deadlocks on resume. The patches were posted also [2].

https://lore.kernel.org/linux-ide/[email protected]/T/#t

Quoted 8 lines

Quoted 2 lines

Unfortunately that didn't work, as /dev/sda no longer exists. Will reply to the patch I bisected the issue to...

With libata/for-next (fa2259a59966c005 ("ata: libata: Cleanup inline DMA helper functions")) and commit 99626085d036ec32 ("ata: libata-scsi:
link ata port and scsi device") reverted, it behaves as before (disk is spun up when system resume completes, no delay when accessing the disk from userspace).

I will check the ata platform driver for R-CAR. I may have overlooked something in that area. I tested with AHCI and libsas adapters only as I do not have ATA on the few ARM SBC boards I have. And I do not have an R-CAR board.

What surprises me is that you need to revert ata: libata: Cleanup inline DMA helper functions". This patch has 0 functional changes and really is only a code cleanup... Nothing should change with it. Can you confirm that you really need to revert that patch to get things working again ?

Quoted 6 lines

Thanks for the report. The delay for the first data access from user space right after resume is 100% expected, with or without this patch. The reason is that waking up the drive (spinning it up) is done asynchronously from the PM resume context, so when you get "PM suspend exit" message signaling that the system is resumed, the drive may not yet be spinning. Any access will wait for that to happen before proceeding. Depending on the drive that can take up to 10s or so.

That does not match with what I am seeing: before this patch, there was no delay on first data access from user space, as the drive is fully spun up when system resume returns.

With this patch, system resume returns earlier, and the drive is only spun up when user space starts accessing data.

Note that I do not have any file system mounted, and use "hd /dev/sda | head -70" to access the disk.

Quoted 6 lines

I am not entirely sure where the net win you see come from. But the patch you mention is in fact completely wrong and does not fix the underlying issues with ata suspend/resume and potential deadlocks in PM due to ata ports relationship with scsi devices. So I have been working on fixing this for the last 2 weeks, after another user also reported issues with the patch you mention [1].

Quoted 5 lines

Could you try libata for-next branch on your system ? There are 7 fix patches in there that I plan to send out for 6.6-rc2 to fix the patch in question and other issues potentially causing deadlocks on resume. The patches were posted also [2].

https://lore.kernel.org/linux-ide/[email protected]/T/#t

Unfortunately that didn't work, as /dev/sda no longer exists. Will reply to the patch I bisected the issue to...

Quoted 10 lines · Geert Uytterhoeven

Quoted 6 lines

Thanks for the report. The delay for the first data access from user space right after resume is 100% expected, with or without this patch. The reason is that waking up the drive (spinning it up) is done asynchronously from the PM resume context, so when you get "PM suspend exit" message signaling that the system is resumed, the drive may not yet be spinning. Any access will wait for that to happen before proceeding. Depending on the drive that can take up to 10s or so.

That does not match with what I am seeing: before this patch, there was no delay on first data access from user space, as the drive is fully spun up when system resume returns.

Yes, that is a possibility, but not by design. Some users have complained about the long resume times which causes laptop screens to be "black" until disks spin up. That did not happen before 5.16, when the change to scsi using the PM async ops to do suspend/resume created all the issues with suspend/resume on ata side. I am going to run 5.15 again to check.

The patch "do not issue START STOP UNIT on resume" was a botch attempt to remove this delay. But it is a bad one because the ATA specs define that a drive can get out of standby (spun down) power state only with a media access command (a VERIFY command is used to spin up the disk). And furthermore, the specs also says that even a reset shall not change the device power state. So issuing a VERIFY command to spin up the drive is required per specs. Note that I do see many of my drives (I have hundreds in the lab) spinning up on reset, which is against the specs. But not all of them. So with the patch "do not issue START STOP UNIT on resume", one risks not seeing the drive resuming correctly (timeout errors on IDENTIFY command issued on resume will get the drive removed).

Quoted 2 lines

With this patch, system resume returns earlier, and the drive is only spun up when user space starts accessing data.

Yes, but "when user space starts accessing data" -> "user space accesses are processed only after the drive completes spinning up" would be more accurate.

That is by design and expected. This is the behavior one would see if the drive is set to use standby timers (to go to standby on its own after some idle time) or if runtime suspend is used. I do not see any issue with this behavior. Is this causing any issue on your end ? Do you have concerns about this approach ?

Having the resume process wait for the drive to fully spin-up is easy to do. But as I mentioned, many users are really not happy about how slow resuming become with that. If I do that, you will get back the previous behavior you mention, but I will be again getting emails about "resume is broken".

I made a decision: no waiting for spinup. That causes a delay for the user on first access, but that makes resume overall far faster. I do not want to go back on that, unless you can confirm that there is a real regression/error/data corruption happening.

Hi Damien,

Quoted 29 lines · Damien Le Moal

Quoted 10 lines · Geert Uytterhoeven

Quoted 6 lines

Thanks for the report. The delay for the first data access from user space right after resume is 100% expected, with or without this patch. The reason is that waking up the drive (spinning it up) is done asynchronously from the PM resume context, so when you get "PM suspend exit" message signaling that the system is resumed, the drive may not yet be spinning. Any access will wait for that to happen before proceeding. Depending on the drive that can take up to 10s or so.

That does not match with what I am seeing: before this patch, there was no delay on first data access from user space, as the drive is fully spun up when system resume returns.

Yes, that is a possibility, but not by design. Some users have complained about the long resume times which causes laptop screens to be "black" until disks spin up. That did not happen before 5.16, when the change to scsi using the PM async ops to do suspend/resume created all the issues with suspend/resume on ata side. I am going to run 5.15 again to check.

The patch "do not issue START STOP UNIT on resume" was a botch attempt to remove this delay. But it is a bad one because the ATA specs define that a drive can get out of standby (spun down) power state only with a media access command (a VERIFY command is used to spin up the disk). And furthermore, the specs also says that even a reset shall not change the device power state. So issuing a VERIFY command to spin up the drive is required per specs. Note that I do see many of my drives (I have hundreds in the lab) spinning up on reset, which is against the specs. But not all of them. So with the patch "do not issue START STOP UNIT on resume", one risks not seeing the drive resuming correctly (timeout errors on IDENTIFY command issued on resume will get the drive removed).

Quoted 5 lines

Quoted 2 lines

With this patch, system resume returns earlier, and the drive is only spun up when user space starts accessing data.

Yes, but "when user space starts accessing data" -> "user space accesses are processed only after the drive completes spinning up" would be more accurate.

Sure, I wrote it down in terms of what the user is experiencing, which may not be identical to what's happening under the hood.

Quoted 10 lines

That is by design and expected. This is the behavior one would see if the drive is set to use standby timers (to go to standby on its own after some idle time) or if runtime suspend is used. I do not see any issue with this behavior. Is this causing any issue on your end ? Do you have concerns about this approach ?

Having the resume process wait for the drive to fully spin-up is easy to do. But as I mentioned, many users are really not happy about how slow resuming become with that. If I do that, you will get back the previous behavior you mention, but I will be again getting emails about "resume is broken".

Quoted 4 lines

I made a decision: no waiting for spinup. That causes a delay for the user on first access, but that makes resume overall far faster. I do not want to go back on that, unless you can confirm that there is a real regression/error/data corruption happening.

I agree that is fine.

Gr{oetje,eeting}s,

Geert

VERIFY command is used to spin up the disk). And furthermore, the specs also says that even a reset shall not change the device power state. So issuing a VERIFY command to spin up the drive is required per specs. Note that I do see many of my drives (I have hundreds in the lab) spinning up on reset, which is against the specs. But not all of them. So with the patch "do not issue START STOP UNIT on resume", one risks not seeing the drive resuming correctly (timeout errors on IDENTIFY command issued on resume will get the drive removed).