Attachment 145614 Details for Bug 75985 – HDA runtime PM debug patch for v5.3

[patch] HDA runtime PM debug patch for v5.3

hda_runpm_debug.patch-5.3 (text/plain), 8.33 KB, created by Lukas Wunner on 2019-10-02 12:32:51 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Lukas Wunner

Created: 2019-10-02 12:32:51 UTC

Size: 8.33 KB

patch

obsolete

>diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
>index b75335508d2c..3eba9ecd24f9 100644
>--- a/drivers/base/power/runtime.c
>+++ b/drivers/base/power/runtime.c
>@@ -399,10 +399,11 @@ static int rpm_idle(struct device *dev, int rpmflags)
> 	int (*callback)(struct device *);
> 	int retval;
> 
>+	dev_info(dev, "%s: begin, rpmflags = %d\n", __func__, rpmflags);
> 	trace_rpm_idle_rcuidle(dev, rpmflags);
> 	retval = rpm_check_suspend_allowed(dev);
> 	if (retval < 0)
>-		;	/* Conditions are wrong. */
>+		dev_info(dev, "%s: rpm_check_suspend_allowed() returned %d\n", __func__, retval);	/* Conditions are wrong. */
> 
> 	/* Idle notifications are allowed only in the RPM_ACTIVE state. */
> 	else if (dev->power.runtime_status != RPM_ACTIVE)
>@@ -435,6 +436,7 @@ static int rpm_idle(struct device *dev, int rpmflags)
> 			dev->power.request_pending = true;
> 			queue_work(pm_wq, &dev->power.work);
> 		}
>+		dev_info(dev, "%s: queued async idle\n", __func__);
> 		trace_rpm_return_int_rcuidle(dev, _THIS_IP_, 0);
> 		return 0;
> 	}
>@@ -443,14 +445,17 @@ static int rpm_idle(struct device *dev, int rpmflags)
> 
> 	callback = RPM_GET_CALLBACK(dev, runtime_idle);
> 
>-	if (callback)
>+	if (callback) {
>+		dev_info(dev, "%s: before rpm_callback()\n", __func__);
> 		retval = __rpm_callback(callback, dev);
>-
>+		dev_info(dev, "%s: after rpm_callback()\n", __func__);
>+	}
> 	dev->power.idle_notification = false;
> 	wake_up_all(&dev->power.wait_queue);
> 
>  out:
> 	trace_rpm_return_int_rcuidle(dev, _THIS_IP_, retval);
>+	dev_info(dev, "%s: end, retval = %d\n", __func__, retval);
> 	return retval ? retval : rpm_suspend(dev, rpmflags | RPM_AUTO);
> }
> 
>@@ -518,12 +523,13 @@ static int rpm_suspend(struct device *dev, int rpmflags)
> 	int retval;
> 
> 	trace_rpm_suspend_rcuidle(dev, rpmflags);
>+	dev_info(dev, "%s: begin, rpmflags = %d\n", __func__, rpmflags);
> 
>  repeat:
> 	retval = rpm_check_suspend_allowed(dev);
> 
> 	if (retval < 0)
>-		;	/* Conditions are wrong. */
>+		dev_info(dev, "%s: rpm_check_suspend_allowed() returned %d\n", __func__, retval);	/* Conditions are wrong. */
> 
> 	/* Synchronous suspends are not allowed in the RPM_RESUMING state. */
> 	else if (dev->power.runtime_status == RPM_RESUMING &&
>@@ -616,6 +622,7 @@ static int rpm_suspend(struct device *dev, int rpmflags)
> 			dev->power.request_pending = true;
> 			queue_work(pm_wq, &dev->power.work);
> 		}
>+		dev_info(dev, "%s: queued async suspend\n", __func__);
> 		goto out;
> 	}
> 
>@@ -624,9 +631,13 @@ static int rpm_suspend(struct device *dev, int rpmflags)
> 	callback = RPM_GET_CALLBACK(dev, runtime_suspend);
> 
> 	dev_pm_enable_wake_irq_check(dev, true);
>+	dev_info(dev, "%s: before rpm_callback()\n", __func__);
> 	retval = rpm_callback(callback, dev);
>-	if (retval)
>+	dev_info(dev, "%s: after rpm_callback()\n", __func__);
>+	if (retval) {
>+		dev_info(dev, "%s: rpm_callback() returned %d\n", __func__, retval);
> 		goto fail;
>+	}
> 
>  no_callback:
> 	__update_runtime_status(dev, RPM_SUSPENDED);
>@@ -642,6 +653,7 @@ static int rpm_suspend(struct device *dev, int rpmflags)
> 		dev->power.deferred_resume = false;
> 		rpm_resume(dev, 0);
> 		retval = -EAGAIN;
>+		dev_info(dev, "%s: carried out deferred resume\n", __func__);
> 		goto out;
> 	}
> 
>@@ -658,7 +670,7 @@ static int rpm_suspend(struct device *dev, int rpmflags)
> 
>  out:
> 	trace_rpm_return_int_rcuidle(dev, _THIS_IP_, retval);
>-
>+	dev_info(dev, "%s: end, retval = %d\n", __func__, retval);
> 	return retval;
> 
>  fail:
>@@ -846,6 +858,7 @@ static int rpm_resume(struct device *dev, int rpmflags)
> 	callback = RPM_GET_CALLBACK(dev, runtime_resume);
> 
> 	dev_pm_disable_wake_irq_check(dev);
>+	dev_info(dev, "rpm_resume\n");
> 	retval = rpm_callback(callback, dev);
> 	if (retval) {
> 		__update_runtime_status(dev, RPM_SUSPENDED);
>diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
>index a8124e47bf6e..f7f844ff9799 100644
>--- a/drivers/pci/pci-driver.c
>+++ b/drivers/pci/pci-driver.c
>@@ -1295,7 +1295,7 @@ static int pci_pm_runtime_suspend(struct device *dev)
> 		 * log level.
> 		 */
> 		if (error == -EBUSY || error == -EAGAIN) {
>-			dev_dbg(dev, "can't suspend now (%ps returned %d)\n",
>+			dev_info(dev, "can't suspend now (%ps returned %d)\n",
> 				pm->runtime_suspend, error);
> 			return error;
> 		} else if (error) {
>diff --git a/sound/pci/hda/hda_intel.c b/sound/pci/hda/hda_intel.c
>index 99fc0917339b..2f3e4acc0e49 100644
>--- a/sound/pci/hda/hda_intel.c
>+++ b/sound/pci/hda/hda_intel.c
>@@ -960,24 +960,31 @@ static int param_set_xint(const char *val, const struct kernel_param *kp)
> /*
>  * power management
>  */
>-static bool azx_is_pm_ready(struct snd_card *card)
>+static bool azx_is_pm_ready(struct device *dev, struct snd_card *card)
> {
> 	struct azx *chip;
> 	struct hda_intel *hda;
> 
>-	if (!card)
>+	if (!card) {
>+		dev_info(dev, "%s: !card\n", __func__);
> 		return false;
>+	}
> 	chip = card->private_data;
> 	hda = container_of(chip, struct hda_intel, chip);
>-	if (chip->disabled || hda->init_failed || !chip->running)
>+	if (chip->disabled || hda->init_failed || !chip->running) {
>+		dev_info(dev, "%s: chip->disabled=%d || hda->init_failed=%d || !chip->running=%d\n", __func__, chip->disabled, hda->init_failed, !chip->running);
> 		return false;
>+	}
> 	return true;
> }
> 
>-static void __azx_runtime_suspend(struct azx *chip)
>+static void __azx_runtime_suspend(struct device *dev, struct azx *chip)
> {
>+	dev_info(dev, "%s: calling azx_stop_chip()\n", __func__);
> 	azx_stop_chip(chip);
>+	dev_info(dev, "%s: calling azx_enter_link_reset()\n", __func__);
> 	azx_enter_link_reset(chip);
>+	dev_info(dev, "%s: calling azx_clear_irq_pending()\n", __func__);
> 	azx_clear_irq_pending(chip);
> 	display_power(chip, false);
> }
>@@ -1018,13 +1025,13 @@ static int azx_suspend(struct device *dev)
> 	struct azx *chip;
> 	struct hdac_bus *bus;
> 
>-	if (!azx_is_pm_ready(card))
>+	if (!azx_is_pm_ready(dev, card))
> 		return 0;
> 
> 	chip = card->private_data;
> 	bus = azx_bus(chip);
> 	snd_power_change_state(card, SNDRV_CTL_POWER_D3hot);
>-	__azx_runtime_suspend(chip);
>+	__azx_runtime_suspend(dev, chip);
> 	if (bus->irq >= 0) {
> 		free_irq(bus->irq, chip);
> 		bus->irq = -1;
>@@ -1042,7 +1049,7 @@ static int azx_resume(struct device *dev)
> 	struct snd_card *card = dev_get_drvdata(dev);
> 	struct azx *chip;
> 
>-	if (!azx_is_pm_ready(card))
>+	if (!azx_is_pm_ready(dev, card))
> 		return 0;
> 
> 	chip = card->private_data;
>@@ -1091,17 +1098,23 @@ static int azx_runtime_suspend(struct device *dev)
> 	struct snd_card *card = dev_get_drvdata(dev);
> 	struct azx *chip;
> 
>-	if (!azx_is_pm_ready(card))
>+	if (!azx_is_pm_ready(dev, card)) {
>+		dev_info(dev, "%s: !azx_is_pm_ready(chip)\n", __func__);
> 		return 0;
>+	}
> 	chip = card->private_data;
>-	if (!azx_has_pm_runtime(chip))
>+	if (!azx_has_pm_runtime(chip)) {
>+		dev_info(dev, "%s: !azx_has_pm_runtime(chip)\n", __func__);
> 		return 0;
>+	}
> 
> 	/* enable controller wake up event */
>+	dev_info(dev, "%s: calling azx_writew()\n", __func__);
> 	azx_writew(chip, WAKEEN, azx_readw(chip, WAKEEN) |
> 		  STATESTS_INT_MASK);
> 
>-	__azx_runtime_suspend(chip);
>+	__azx_runtime_suspend(dev, chip);
>+	dev_info(dev, "%s: finished\n", __func__);
> 	trace_azx_runtime_suspend(chip);
> 	return 0;
> }
>@@ -1111,7 +1124,7 @@ static int azx_runtime_resume(struct device *dev)
> 	struct snd_card *card = dev_get_drvdata(dev);
> 	struct azx *chip;
> 
>-	if (!azx_is_pm_ready(card))
>+	if (!azx_is_pm_ready(dev, card))
> 		return 0;
> 	chip = card->private_data;
> 	if (!azx_has_pm_runtime(chip))
>@@ -1132,21 +1145,28 @@ static int azx_runtime_idle(struct device *dev)
> 	struct azx *chip;
> 	struct hda_intel *hda;
> 
>-	if (!card)
>+	if (!card) {
>+		dev_info(dev, "%s: !card\n", __func__);
> 		return 0;
>+	}
> 
> 	chip = card->private_data;
> 	hda = container_of(chip, struct hda_intel, chip);
>-	if (chip->disabled || hda->init_failed)
>+	if (chip->disabled || hda->init_failed) {
>+		dev_info(dev, "%s: chip->disabled=%d || hda->init_failed=%d\n", __func__, chip->disabled, hda->init_failed);
> 		return 0;
>+	}
> 
>+	dev_info(dev, "%s: !power_save_controller=%d || !azx_has_pm_runtime(chip)=%d || azx_bus(chip)->codec_powered=%#lx || !chip->running=%d\n", __func__, !power_save_controller, !azx_has_pm_runtime(chip), azx_bus(chip)->codec_powered, !chip->running);
> 	if (!power_save_controller || !azx_has_pm_runtime(chip) ||
> 	    azx_bus(chip)->codec_powered || !chip->running)
> 		return -EBUSY;
> 
> 	/* ELD notification gets broken when HD-audio bus is off */
>-	if (needs_eld_notify_link(hda))
>+	if (needs_eld_notify_link(hda)) {
>+		dev_info(dev, "%s: needs_eld_notify_link(hda)\n", __func__);
> 		return -EBUSY;
>+	}
> 
> 	return 0;
> }

Actions: View | Splinter Review

Attachments on bug 75985: 95562 | 128640 | 136369 | 136416 | 136418 | 137764 | 137939 | 137940 | 137941 | 137989 | 144596 | 145614 | 145615 | 145616 | 145627 | 145640 | 145778 | 145830

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.