[PATCH v2 0/9] PCI: Use PCIe service name in dmesg logs

[PATCH v2 0/9] PCI: Use PCIe service name in dmesg logs

[Frederick Lawler]

In referrence to [1], PCIe services did not have uniform logging via pci_*()
printk wrappers. Add dev_fmt() to each service, clean up dmesg logs,
use pci_dbg() for hotplug debug messages, and lastly, uniformally
add Slot(%s) prefixes to hotplug ctrl_*() wrappers.

1. https://lore.kernel.org/linux-pci/20190308180149.GD214730@google.com/

Changes from v1:
 - Split dev_fmt() additions into own patches per service
 - Kept ctrl_*() wrappers and applied "Slot(%s)" prefix to messages
 - Attempted to leave no log gaps between patches

Frederick Lawler (9):
  PCI/AER: Cleanup dmesg logs
  PCI/DPC: Prefix dmesg logs with PCIe service name
  PCI/PME: Prefix dmesg logs with PCIe service name
  PCI/LINK: Prefix dmesg logs with PCIe service name
  PCI/AER: Prefix dmesg logs with PCIe service name
  PCI: hotplug: Prefix dmesg logs with PCIe service name
  PCI: hotplug: Prefer CONFIG_DYNAMIC_DEBUG/DEBUG for dmesg logs
  PCI: hotplug: Remove unnecessary dbg/err/info/warn() printk() wrappers
  PCI: hotplug: Prefix ctrl_*() dmesg logs with pciehp slot name

 drivers/pci/hotplug/pciehp.h       | 28 ++++----------
 drivers/pci/hotplug/pciehp_core.c  | 20 ++++++----
 drivers/pci/hotplug/pciehp_ctrl.c  | 60 ++++++++++++------------------
 drivers/pci/hotplug/pciehp_hpc.c   |  9 +++--
 drivers/pci/hotplug/pciehp_pci.c   |  2 +
 drivers/pci/pcie/aer.c             | 19 ++++++----
 drivers/pci/pcie/aer_inject.c      |  6 ++-
 drivers/pci/pcie/bw_notification.c |  2 +
 drivers/pci/pcie/dpc.c             | 37 +++++++++---------
 drivers/pci/pcie/pme.c             |  2 +
 10 files changed, 89 insertions(+), 96 deletions(-)

--
2.17.1

[PATCH v2 1/9] PCI/AER: Cleanup dmesg logs

[Frederick Lawler]

Cleanup dmesg logs.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/pcie/aer.c | 11 +++++------
 1 file changed, 5 insertions(+), 6 deletions(-)

diff --git a/drivers/pci/pcie/aer.c b/drivers/pci/pcie/aer.c
index f8fc2114ad39..82eb45335b6f 100644
--- a/drivers/pci/pcie/aer.c
+++ b/drivers/pci/pcie/aer.c
@@ -964,8 +964,8 @@ static bool find_source_device(struct pci_dev *parent,
 	pci_walk_bus(parent->subordinate, find_device_iter, e_info);
 
 	if (!e_info->error_dev_num) {
-		pci_printk(KERN_DEBUG, parent, "can't find device of ID%04x\n",
-			   e_info->id);
+		pci_info(parent, "can't find device of ID%04x\n",
+			 e_info->id);
 		return false;
 	}
 	return true;
@@ -1380,7 +1380,6 @@ static int aer_probe(struct pcie_device *dev)
 
 	rpc = devm_kzalloc(device, sizeof(struct aer_rpc), GFP_KERNEL);
 	if (!rpc) {
-		dev_printk(KERN_DEBUG, device, "alloc AER rpc failed\n");
 		return -ENOMEM;
 	}
 	rpc->rpd = dev->port;
@@ -1389,8 +1388,8 @@ static int aer_probe(struct pcie_device *dev)
 	status = devm_request_threaded_irq(device, dev->irq, aer_irq, aer_isr,
 					   IRQF_SHARED, "aerdrv", dev);
 	if (status) {
-		dev_printk(KERN_DEBUG, device, "request AER IRQ %d failed\n",
-			   dev->irq);
+		dev_err(device, "request AER IRQ %d failed\n",
+			dev->irq);
 		return status;
 	}
 
@@ -1419,7 +1418,7 @@ static pci_ers_result_t aer_root_reset(struct pci_dev *dev)
 	pci_write_config_dword(dev, pos + PCI_ERR_ROOT_COMMAND, reg32);
 
 	rc = pci_bus_error_reset(dev);
-	pci_printk(KERN_DEBUG, dev, "Root Port link has been reset\n");
+	pci_info(dev, "Root Port link has been reset\n");
 
 	/* Clear Root Error Status */
 	pci_read_config_dword(dev, pos + PCI_ERR_ROOT_STATUS, &reg32);
-- 
2.17.1

Re: [PATCH v2 1/9] PCI/AER: Cleanup dmesg logs

[Bjorn Helgaas]

On Thu, May 02, 2019 at 10:59:38PM -0500, Frederick Lawler wrote:
> Cleanup dmesg logs.

To specific, I think you did this:

  - Drop the kzalloc() failure message because those failures are logged
    elsewhere.

  - Convert other printk(KERN_DEBUG) to pci_info() or dev_err() as
    appropriate because printk(KERN_DEBUG) is ugly and don't match the
    other logging.  These could have been converted to pci_dbg() or
    dev_dbg() instead, but that would make them depend on
    CONFIG_DYNAMIC_DEBUG or DEBUG, and these messages are important enough
    that we always want them.

I think the summary (subject line) is something like:

  PCI/AER: Convert printk(KERN_DEBUG) to pci_info() or dev_err()

> Signed-off-by: Frederick Lawler <fred@fredlawl.com>
> ---
>  drivers/pci/pcie/aer.c | 11 +++++------
>  1 file changed, 5 insertions(+), 6 deletions(-)
> 
> diff --git a/drivers/pci/pcie/aer.c b/drivers/pci/pcie/aer.c
> index f8fc2114ad39..82eb45335b6f 100644
> --- a/drivers/pci/pcie/aer.c
> +++ b/drivers/pci/pcie/aer.c
> @@ -964,8 +964,8 @@ static bool find_source_device(struct pci_dev *parent,
>  	pci_walk_bus(parent->subordinate, find_device_iter, e_info);
>  
>  	if (!e_info->error_dev_num) {
> -		pci_printk(KERN_DEBUG, parent, "can't find device of ID%04x\n",
> -			   e_info->id);
> +		pci_info(parent, "can't find device of ID%04x\n",
> +			 e_info->id);
>  		return false;
>  	}
>  	return true;
> @@ -1380,7 +1380,6 @@ static int aer_probe(struct pcie_device *dev)
>  
>  	rpc = devm_kzalloc(device, sizeof(struct aer_rpc), GFP_KERNEL);
>  	if (!rpc) {
> -		dev_printk(KERN_DEBUG, device, "alloc AER rpc failed\n");
>  		return -ENOMEM;
>  	}
>  	rpc->rpd = dev->port;
> @@ -1389,8 +1388,8 @@ static int aer_probe(struct pcie_device *dev)
>  	status = devm_request_threaded_irq(device, dev->irq, aer_irq, aer_isr,
>  					   IRQF_SHARED, "aerdrv", dev);
>  	if (status) {
> -		dev_printk(KERN_DEBUG, device, "request AER IRQ %d failed\n",
> -			   dev->irq);
> +		dev_err(device, "request AER IRQ %d failed\n",
> +			dev->irq);
>  		return status;
>  	}
>  
> @@ -1419,7 +1418,7 @@ static pci_ers_result_t aer_root_reset(struct pci_dev *dev)
>  	pci_write_config_dword(dev, pos + PCI_ERR_ROOT_COMMAND, reg32);
>  
>  	rc = pci_bus_error_reset(dev);
> -	pci_printk(KERN_DEBUG, dev, "Root Port link has been reset\n");
> +	pci_info(dev, "Root Port link has been reset\n");
>  
>  	/* Clear Root Error Status */
>  	pci_read_config_dword(dev, pos + PCI_ERR_ROOT_STATUS, &reg32);
> -- 
> 2.17.1
> 

Re: [PATCH v2 1/9] PCI/AER: Cleanup dmesg logs

[Andy Shevchenko]

On Thu, May 02, 2019 at 10:59:38PM -0500, Frederick Lawler wrote:
> Cleanup dmesg logs.

> @@ -1380,7 +1380,6 @@ static int aer_probe(struct pcie_device *dev)
>  
>  	rpc = devm_kzalloc(device, sizeof(struct aer_rpc), GFP_KERNEL);
>  	if (!rpc) {
> -		dev_printk(KERN_DEBUG, device, "alloc AER rpc failed\n");
>  		return -ENOMEM;
>  	}

When you will do a next version consider to drop no needed {} above.

-- 
With Best Regards,
Andy Shevchenko

[PATCH v2 2/9] PCI/DPC: Prefix dmesg logs with PCIe service name

[Frederick Lawler]

Prefix dmesg logs with PCIe service name.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/pcie/dpc.c | 37 ++++++++++++++++++-------------------
 1 file changed, 18 insertions(+), 19 deletions(-)

diff --git a/drivers/pci/pcie/dpc.c b/drivers/pci/pcie/dpc.c
index 7b77754a82de..934391c91c23 100644
--- a/drivers/pci/pcie/dpc.c
+++ b/drivers/pci/pcie/dpc.c
@@ -6,6 +6,8 @@
  * Copyright (C) 2016 Intel Corp.
  */
 
+#define dev_fmt(fmt) "DPC: " fmt
+
 #include <linux/aer.h>
 #include <linux/delay.h>
 #include <linux/interrupt.h>
@@ -100,7 +102,6 @@ static int dpc_wait_rp_inactive(struct dpc_dev *dpc)
 {
 	unsigned long timeout = jiffies + HZ;
 	struct pci_dev *pdev = dpc->dev->port;
-	struct device *dev = &dpc->dev->device;
 	u16 cap = dpc->cap_pos, status;
 
 	pci_read_config_word(pdev, cap + PCI_EXP_DPC_STATUS, &status);
@@ -110,7 +111,7 @@ static int dpc_wait_rp_inactive(struct dpc_dev *dpc)
 		pci_read_config_word(pdev, cap + PCI_EXP_DPC_STATUS, &status);
 	}
 	if (status & PCI_EXP_DPC_RP_BUSY) {
-		dev_warn(dev, "DPC root port still busy\n");
+		pci_warn(pdev, "DPC root port still busy\n");
 		return -EBUSY;
 	}
 	return 0;
@@ -148,7 +149,6 @@ static pci_ers_result_t dpc_reset_link(struct pci_dev *pdev)
 
 static void dpc_process_rp_pio_error(struct dpc_dev *dpc)
 {
-	struct device *dev = &dpc->dev->device;
 	struct pci_dev *pdev = dpc->dev->port;
 	u16 cap = dpc->cap_pos, dpc_status, first_error;
 	u32 status, mask, sev, syserr, exc, dw0, dw1, dw2, dw3, log, prefix;
@@ -156,13 +156,13 @@ static void dpc_process_rp_pio_error(struct dpc_dev *dpc)
 
 	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_STATUS, &status);
 	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_MASK, &mask);
-	dev_err(dev, "rp_pio_status: %#010x, rp_pio_mask: %#010x\n",
+	pci_err(pdev, "rp_pio_status: %#010x, rp_pio_mask: %#010x\n",
 		status, mask);
 
 	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_SEVERITY, &sev);
 	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_SYSERROR, &syserr);
 	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_EXCEPTION, &exc);
-	dev_err(dev, "RP PIO severity=%#010x, syserror=%#010x, exception=%#010x\n",
+	pci_err(pdev, "RP PIO severity=%#010x, syserror=%#010x, exception=%#010x\n",
 		sev, syserr, exc);
 
 	/* Get First Error Pointer */
@@ -171,7 +171,7 @@ static void dpc_process_rp_pio_error(struct dpc_dev *dpc)
 
 	for (i = 0; i < ARRAY_SIZE(rp_pio_error_string); i++) {
 		if ((status & ~mask) & (1 << i))
-			dev_err(dev, "[%2d] %s%s\n", i, rp_pio_error_string[i],
+			pci_err(pdev, "[%2d] %s%s\n", i, rp_pio_error_string[i],
 				first_error == i ? " (First)" : "");
 	}
 
@@ -185,18 +185,18 @@ static void dpc_process_rp_pio_error(struct dpc_dev *dpc)
 			      &dw2);
 	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_HEADER_LOG + 12,
 			      &dw3);
-	dev_err(dev, "TLP Header: %#010x %#010x %#010x %#010x\n",
+	pci_err(pdev, "TLP Header: %#010x %#010x %#010x %#010x\n",
 		dw0, dw1, dw2, dw3);
 
 	if (dpc->rp_log_size < 5)
 		goto clear_status;
 	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_IMPSPEC_LOG, &log);
-	dev_err(dev, "RP PIO ImpSpec Log %#010x\n", log);
+	pci_err(pdev, "RP PIO ImpSpec Log %#010x\n", log);
 
 	for (i = 0; i < dpc->rp_log_size - 5; i++) {
 		pci_read_config_dword(pdev,
 			cap + PCI_EXP_DPC_RP_PIO_TLPPREFIX_LOG, &prefix);
-		dev_err(dev, "TLP Prefix Header: dw%d, %#010x\n", i, prefix);
+		pci_err(pdev, "TLP Prefix Header: dw%d, %#010x\n", i, prefix);
 	}
  clear_status:
 	pci_write_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_STATUS, status);
@@ -229,18 +229,17 @@ static irqreturn_t dpc_handler(int irq, void *context)
 	struct aer_err_info info;
 	struct dpc_dev *dpc = context;
 	struct pci_dev *pdev = dpc->dev->port;
-	struct device *dev = &dpc->dev->device;
 	u16 cap = dpc->cap_pos, status, source, reason, ext_reason;
 
 	pci_read_config_word(pdev, cap + PCI_EXP_DPC_STATUS, &status);
 	pci_read_config_word(pdev, cap + PCI_EXP_DPC_SOURCE_ID, &source);
 
-	dev_info(dev, "DPC containment event, status:%#06x source:%#06x\n",
+	pci_info(pdev, "DPC containment event, status:%#06x source:%#06x\n",
 		 status, source);
 
 	reason = (status & PCI_EXP_DPC_STATUS_TRIGGER_RSN) >> 1;
 	ext_reason = (status & PCI_EXP_DPC_STATUS_TRIGGER_RSN_EXT) >> 5;
-	dev_warn(dev, "DPC %s detected\n",
+	pci_warn(pdev, "DPC %s detected\n",
 		 (reason == 0) ? "unmasked uncorrectable error" :
 		 (reason == 1) ? "ERR_NONFATAL" :
 		 (reason == 2) ? "ERR_FATAL" :
@@ -307,7 +306,7 @@ static int dpc_probe(struct pcie_device *dev)
 					   dpc_handler, IRQF_SHARED,
 					   "pcie-dpc", dpc);
 	if (status) {
-		dev_warn(device, "request IRQ%d failed: %d\n", dev->irq,
+		pci_warn(pdev, "request IRQ%d failed: %d\n", dev->irq,
 			 status);
 		return status;
 	}
@@ -319,7 +318,7 @@ static int dpc_probe(struct pcie_device *dev)
 	if (dpc->rp_extensions) {
 		dpc->rp_log_size = (cap & PCI_EXP_DPC_RP_PIO_LOG_SIZE) >> 8;
 		if (dpc->rp_log_size < 4 || dpc->rp_log_size > 9) {
-			dev_err(device, "RP PIO log size %u is invalid\n",
+			pci_err(pdev, "RP PIO log size %u is invalid\n",
 				dpc->rp_log_size);
 			dpc->rp_log_size = 0;
 		}
@@ -328,11 +327,11 @@ static int dpc_probe(struct pcie_device *dev)
 	ctl = (ctl & 0xfff4) | PCI_EXP_DPC_CTL_EN_FATAL | PCI_EXP_DPC_CTL_INT_EN;
 	pci_write_config_word(pdev, dpc->cap_pos + PCI_EXP_DPC_CTL, ctl);
 
-	dev_info(device, "DPC error containment capabilities: Int Msg #%d, RPExt%c PoisonedTLP%c SwTrigger%c RP PIO Log %d, DL_ActiveErr%c\n",
-		cap & PCI_EXP_DPC_IRQ, FLAG(cap, PCI_EXP_DPC_CAP_RP_EXT),
-		FLAG(cap, PCI_EXP_DPC_CAP_POISONED_TLP),
-		FLAG(cap, PCI_EXP_DPC_CAP_SW_TRIGGER), dpc->rp_log_size,
-		FLAG(cap, PCI_EXP_DPC_CAP_DL_ACTIVE));
+	pci_info(pdev, "DPC error containment capabilities: Int Msg #%d, RPExt%c PoisonedTLP%c SwTrigger%c RP PIO Log %d, DL_ActiveErr%c\n",
+		 cap & PCI_EXP_DPC_IRQ, FLAG(cap, PCI_EXP_DPC_CAP_RP_EXT),
+		 FLAG(cap, PCI_EXP_DPC_CAP_POISONED_TLP),
+		 FLAG(cap, PCI_EXP_DPC_CAP_SW_TRIGGER), dpc->rp_log_size,
+		 FLAG(cap, PCI_EXP_DPC_CAP_DL_ACTIVE));
 
 	pci_add_ext_cap_save_buffer(pdev, PCI_EXT_CAP_ID_DPC, sizeof(u16));
 	return status;
-- 
2.17.1

Re: [PATCH v2 2/9] PCI/DPC: Prefix dmesg logs with PCIe service name

[Keith Busch]

On Thu, May 02, 2019 at 08:59:39PM -0700, Frederick Lawler wrote:
> +#define dev_fmt(fmt) "DPC: " fmt
> +

> @@ -110,7 +111,7 @@ static int dpc_wait_rp_inactive(struct dpc_dev *dpc)
> +		pci_warn(pdev, "DPC root port still busy\n");

> @@ -229,18 +229,17 @@ static irqreturn_t dpc_handler(int irq, void *context)
> +	pci_warn(pdev, "DPC %s detected\n",

> @@ -328,11 +327,11 @@ static int dpc_probe(struct pcie_device *dev)
> +	pci_info(pdev, "DPC error containment capabilities: Int Msg #%d, RPExt%c PoisonedTLP%c SwTrigger%c RP PIO Log %d, DL_ActiveErr%c\n",

Since you've already prefixed each print with "DPC: ", the extra "DPC"
in the above prints is redundant.

Re: [PATCH v2 2/9] PCI/DPC: Prefix dmesg logs with PCIe service name

[Bjorn Helgaas]

On Thu, May 02, 2019 at 10:59:39PM -0500, Frederick Lawler wrote:
> Prefix dmesg logs with PCIe service name.

The important thing about this patch is not so much that it adds a
prefix (actually, it basically *moves* the prefix from the driver name
("dpc") to being part of the messages ("DPC:")), but that it changes
the logging from being associated with the pcie_device to the pci_dev.
I think the message change will be something like this (which I would
include in the commit log):

  - dpc 0000:80:10.0:pcie008: DPC error containment capabilities: ...
  + pcieport 0000:80:10.0: DPC: error containment capabilities: ...

with a subject like:

  PCI/DPC: Log messages with pci_dev, not pcie_device

The above example assumes you drop the extra "DPC" as Keith suggested,
which I think I agree with.  Otherwise we'd have:

  + pcieport 0000:80:10.0: DPC: DPC error containment capabilities: ...

which is a little redundant.

You could even include a link like:

Link: https://lore.kernel.org/lkml/20190308180149.GD214730@google.com

> Signed-off-by: Frederick Lawler <fred@fredlawl.com>
> ---
>  drivers/pci/pcie/dpc.c | 37 ++++++++++++++++++-------------------
>  1 file changed, 18 insertions(+), 19 deletions(-)
> 
> diff --git a/drivers/pci/pcie/dpc.c b/drivers/pci/pcie/dpc.c
> index 7b77754a82de..934391c91c23 100644
> --- a/drivers/pci/pcie/dpc.c
> +++ b/drivers/pci/pcie/dpc.c
> @@ -6,6 +6,8 @@
>   * Copyright (C) 2016 Intel Corp.
>   */
>  
> +#define dev_fmt(fmt) "DPC: " fmt
> +
>  #include <linux/aer.h>
>  #include <linux/delay.h>
>  #include <linux/interrupt.h>
> @@ -100,7 +102,6 @@ static int dpc_wait_rp_inactive(struct dpc_dev *dpc)
>  {
>  	unsigned long timeout = jiffies + HZ;
>  	struct pci_dev *pdev = dpc->dev->port;
> -	struct device *dev = &dpc->dev->device;
>  	u16 cap = dpc->cap_pos, status;
>  
>  	pci_read_config_word(pdev, cap + PCI_EXP_DPC_STATUS, &status);
> @@ -110,7 +111,7 @@ static int dpc_wait_rp_inactive(struct dpc_dev *dpc)
>  		pci_read_config_word(pdev, cap + PCI_EXP_DPC_STATUS, &status);
>  	}
>  	if (status & PCI_EXP_DPC_RP_BUSY) {
> -		dev_warn(dev, "DPC root port still busy\n");
> +		pci_warn(pdev, "DPC root port still busy\n");
>  		return -EBUSY;
>  	}
>  	return 0;
> @@ -148,7 +149,6 @@ static pci_ers_result_t dpc_reset_link(struct pci_dev *pdev)
>  
>  static void dpc_process_rp_pio_error(struct dpc_dev *dpc)
>  {
> -	struct device *dev = &dpc->dev->device;
>  	struct pci_dev *pdev = dpc->dev->port;
>  	u16 cap = dpc->cap_pos, dpc_status, first_error;
>  	u32 status, mask, sev, syserr, exc, dw0, dw1, dw2, dw3, log, prefix;
> @@ -156,13 +156,13 @@ static void dpc_process_rp_pio_error(struct dpc_dev *dpc)
>  
>  	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_STATUS, &status);
>  	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_MASK, &mask);
> -	dev_err(dev, "rp_pio_status: %#010x, rp_pio_mask: %#010x\n",
> +	pci_err(pdev, "rp_pio_status: %#010x, rp_pio_mask: %#010x\n",
>  		status, mask);
>  
>  	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_SEVERITY, &sev);
>  	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_SYSERROR, &syserr);
>  	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_EXCEPTION, &exc);
> -	dev_err(dev, "RP PIO severity=%#010x, syserror=%#010x, exception=%#010x\n",
> +	pci_err(pdev, "RP PIO severity=%#010x, syserror=%#010x, exception=%#010x\n",
>  		sev, syserr, exc);
>  
>  	/* Get First Error Pointer */
> @@ -171,7 +171,7 @@ static void dpc_process_rp_pio_error(struct dpc_dev *dpc)
>  
>  	for (i = 0; i < ARRAY_SIZE(rp_pio_error_string); i++) {
>  		if ((status & ~mask) & (1 << i))
> -			dev_err(dev, "[%2d] %s%s\n", i, rp_pio_error_string[i],
> +			pci_err(pdev, "[%2d] %s%s\n", i, rp_pio_error_string[i],
>  				first_error == i ? " (First)" : "");
>  	}
>  
> @@ -185,18 +185,18 @@ static void dpc_process_rp_pio_error(struct dpc_dev *dpc)
>  			      &dw2);
>  	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_HEADER_LOG + 12,
>  			      &dw3);
> -	dev_err(dev, "TLP Header: %#010x %#010x %#010x %#010x\n",
> +	pci_err(pdev, "TLP Header: %#010x %#010x %#010x %#010x\n",
>  		dw0, dw1, dw2, dw3);
>  
>  	if (dpc->rp_log_size < 5)
>  		goto clear_status;
>  	pci_read_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_IMPSPEC_LOG, &log);
> -	dev_err(dev, "RP PIO ImpSpec Log %#010x\n", log);
> +	pci_err(pdev, "RP PIO ImpSpec Log %#010x\n", log);
>  
>  	for (i = 0; i < dpc->rp_log_size - 5; i++) {
>  		pci_read_config_dword(pdev,
>  			cap + PCI_EXP_DPC_RP_PIO_TLPPREFIX_LOG, &prefix);
> -		dev_err(dev, "TLP Prefix Header: dw%d, %#010x\n", i, prefix);
> +		pci_err(pdev, "TLP Prefix Header: dw%d, %#010x\n", i, prefix);
>  	}
>   clear_status:
>  	pci_write_config_dword(pdev, cap + PCI_EXP_DPC_RP_PIO_STATUS, status);
> @@ -229,18 +229,17 @@ static irqreturn_t dpc_handler(int irq, void *context)
>  	struct aer_err_info info;
>  	struct dpc_dev *dpc = context;
>  	struct pci_dev *pdev = dpc->dev->port;
> -	struct device *dev = &dpc->dev->device;
>  	u16 cap = dpc->cap_pos, status, source, reason, ext_reason;
>  
>  	pci_read_config_word(pdev, cap + PCI_EXP_DPC_STATUS, &status);
>  	pci_read_config_word(pdev, cap + PCI_EXP_DPC_SOURCE_ID, &source);
>  
> -	dev_info(dev, "DPC containment event, status:%#06x source:%#06x\n",
> +	pci_info(pdev, "DPC containment event, status:%#06x source:%#06x\n",
>  		 status, source);
>  
>  	reason = (status & PCI_EXP_DPC_STATUS_TRIGGER_RSN) >> 1;
>  	ext_reason = (status & PCI_EXP_DPC_STATUS_TRIGGER_RSN_EXT) >> 5;
> -	dev_warn(dev, "DPC %s detected\n",
> +	pci_warn(pdev, "DPC %s detected\n",
>  		 (reason == 0) ? "unmasked uncorrectable error" :
>  		 (reason == 1) ? "ERR_NONFATAL" :
>  		 (reason == 2) ? "ERR_FATAL" :
> @@ -307,7 +306,7 @@ static int dpc_probe(struct pcie_device *dev)
>  					   dpc_handler, IRQF_SHARED,
>  					   "pcie-dpc", dpc);
>  	if (status) {
> -		dev_warn(device, "request IRQ%d failed: %d\n", dev->irq,
> +		pci_warn(pdev, "request IRQ%d failed: %d\n", dev->irq,
>  			 status);
>  		return status;
>  	}
> @@ -319,7 +318,7 @@ static int dpc_probe(struct pcie_device *dev)
>  	if (dpc->rp_extensions) {
>  		dpc->rp_log_size = (cap & PCI_EXP_DPC_RP_PIO_LOG_SIZE) >> 8;
>  		if (dpc->rp_log_size < 4 || dpc->rp_log_size > 9) {
> -			dev_err(device, "RP PIO log size %u is invalid\n",
> +			pci_err(pdev, "RP PIO log size %u is invalid\n",
>  				dpc->rp_log_size);
>  			dpc->rp_log_size = 0;
>  		}
> @@ -328,11 +327,11 @@ static int dpc_probe(struct pcie_device *dev)
>  	ctl = (ctl & 0xfff4) | PCI_EXP_DPC_CTL_EN_FATAL | PCI_EXP_DPC_CTL_INT_EN;
>  	pci_write_config_word(pdev, dpc->cap_pos + PCI_EXP_DPC_CTL, ctl);
>  
> -	dev_info(device, "DPC error containment capabilities: Int Msg #%d, RPExt%c PoisonedTLP%c SwTrigger%c RP PIO Log %d, DL_ActiveErr%c\n",
> -		cap & PCI_EXP_DPC_IRQ, FLAG(cap, PCI_EXP_DPC_CAP_RP_EXT),
> -		FLAG(cap, PCI_EXP_DPC_CAP_POISONED_TLP),
> -		FLAG(cap, PCI_EXP_DPC_CAP_SW_TRIGGER), dpc->rp_log_size,
> -		FLAG(cap, PCI_EXP_DPC_CAP_DL_ACTIVE));
> +	pci_info(pdev, "DPC error containment capabilities: Int Msg #%d, RPExt%c PoisonedTLP%c SwTrigger%c RP PIO Log %d, DL_ActiveErr%c\n",
> +		 cap & PCI_EXP_DPC_IRQ, FLAG(cap, PCI_EXP_DPC_CAP_RP_EXT),
> +		 FLAG(cap, PCI_EXP_DPC_CAP_POISONED_TLP),
> +		 FLAG(cap, PCI_EXP_DPC_CAP_SW_TRIGGER), dpc->rp_log_size,
> +		 FLAG(cap, PCI_EXP_DPC_CAP_DL_ACTIVE));
>  
>  	pci_add_ext_cap_save_buffer(pdev, PCI_EXT_CAP_ID_DPC, sizeof(u16));
>  	return status;
> -- 
> 2.17.1
> 

[PATCH v2 3/9] PCI/PME: Prefix dmesg logs with PCIe service name

[Frederick Lawler]

Prefix dmesg logs with PCIe service name.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/pcie/pme.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/drivers/pci/pcie/pme.c b/drivers/pci/pcie/pme.c
index 54d593d10396..d6698423a6d6 100644
--- a/drivers/pci/pcie/pme.c
+++ b/drivers/pci/pcie/pme.c
@@ -7,6 +7,8 @@
  * Copyright (C) 2009 Rafael J. Wysocki <rjw@sisk.pl>, Novell Inc.
  */
 
+#define dev_fmt(fmt) "PME: " fmt
+
 #include <linux/pci.h>
 #include <linux/kernel.h>
 #include <linux/errno.h>
-- 
2.17.1

Re: [PATCH v2 3/9] PCI/PME: Prefix dmesg logs with PCIe service name

[Bjorn Helgaas]

On Thu, May 02, 2019 at 10:59:40PM -0500, Frederick Lawler wrote:
> Prefix dmesg logs with PCIe service name.

... to make it consistent with other PCIe services.

It's interesting that there are three uses here:

  pci_dbg(port, "PME interrupt generated for non-existent device ...")
  pci_dbg(port, "Spurious native PME interrupt!\n")
  pci_info(port, "Signaling PME with IRQ %d\n", srv->irq)

The first two use pci_dbg(), so whether it goes anywhere depends on
CONFIG_DYNAMIC_DEBUG and DEBUG.  To me they seem interesting enough to
become pci_info().

And all three already include "PME", so I could go either way with
adding the prefix.  But I agree that having it consistent with the
other services is probably a nice small hint that this is a PCIe port
thing, not an endpoint thing.

> Signed-off-by: Frederick Lawler <fred@fredlawl.com>
> ---
>  drivers/pci/pcie/pme.c | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/drivers/pci/pcie/pme.c b/drivers/pci/pcie/pme.c
> index 54d593d10396..d6698423a6d6 100644
> --- a/drivers/pci/pcie/pme.c
> +++ b/drivers/pci/pcie/pme.c
> @@ -7,6 +7,8 @@
>   * Copyright (C) 2009 Rafael J. Wysocki <rjw@sisk.pl>, Novell Inc.
>   */
>  
> +#define dev_fmt(fmt) "PME: " fmt
> +
>  #include <linux/pci.h>
>  #include <linux/kernel.h>
>  #include <linux/errno.h>
> -- 
> 2.17.1
> 

[PATCH v2 4/9] PCI/LINK: Prefix dmesg logs with PCIe service name

[Frederick Lawler]

bw_notification.c currently does not have any dmesg logs. As the
service continues to expand in functionality, prefix logs anyways.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/pcie/bw_notification.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/drivers/pci/pcie/bw_notification.c b/drivers/pci/pcie/bw_notification.c
index d2eae3b7cc0f..a4bb90562cd5 100644
--- a/drivers/pci/pcie/bw_notification.c
+++ b/drivers/pci/pcie/bw_notification.c
@@ -14,6 +14,8 @@
  * and warns when links become degraded in operation.
  */
 
+#define dev_fmt(fmt) "BWN: " fmt
+
 #include "../pci.h"
 #include "portdrv.h"
 
-- 
2.17.1

Re: [PATCH v2 4/9] PCI/LINK: Prefix dmesg logs with PCIe service name

[Bjorn Helgaas]

On Thu, May 02, 2019 at 10:59:41PM -0500, Frederick Lawler wrote:
> bw_notification.c currently does not have any dmesg logs. As the
> service continues to expand in functionality, prefix logs anyways.
> 
> Signed-off-by: Frederick Lawler <fred@fredlawl.com>
> ---
>  drivers/pci/pcie/bw_notification.c | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/drivers/pci/pcie/bw_notification.c b/drivers/pci/pcie/bw_notification.c
> index d2eae3b7cc0f..a4bb90562cd5 100644
> --- a/drivers/pci/pcie/bw_notification.c
> +++ b/drivers/pci/pcie/bw_notification.c
> @@ -14,6 +14,8 @@
>   * and warns when links become degraded in operation.
>   */
>  
> +#define dev_fmt(fmt) "BWN: " fmt

I think I'd drop this patch until it's needed.

>  #include "../pci.h"
>  #include "portdrv.h"
>  
> -- 
> 2.17.1
> 

[PATCH v2 5/9] PCI/AER: Prefix dmesg logs with PCIe service name

[Frederick Lawler]

Prefix dmesg logs with PCIe service name.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/pcie/aer.c        | 10 +++++++---
 drivers/pci/pcie/aer_inject.c |  6 ++++--
 2 files changed, 11 insertions(+), 5 deletions(-)

diff --git a/drivers/pci/pcie/aer.c b/drivers/pci/pcie/aer.c
index 82eb45335b6f..e603084b8fc1 100644
--- a/drivers/pci/pcie/aer.c
+++ b/drivers/pci/pcie/aer.c
@@ -12,6 +12,9 @@
  *    Andrew Patterson <andrew.patterson@hp.com>
  */
 
+#define pr_fmt(fmt) "AER: " fmt
+#define dev_fmt pr_fmt
+
 #include <linux/cper.h>
 #include <linux/pci.h>
 #include <linux/pci-acpi.h>
@@ -1377,24 +1380,25 @@ static int aer_probe(struct pcie_device *dev)
 	int status;
 	struct aer_rpc *rpc;
 	struct device *device = &dev->device;
+	struct pci_dev *port = dev->port;
 
 	rpc = devm_kzalloc(device, sizeof(struct aer_rpc), GFP_KERNEL);
 	if (!rpc) {
 		return -ENOMEM;
 	}
-	rpc->rpd = dev->port;
+	rpc->rpd = port;
 	set_service_data(dev, rpc);
 
 	status = devm_request_threaded_irq(device, dev->irq, aer_irq, aer_isr,
 					   IRQF_SHARED, "aerdrv", dev);
 	if (status) {
-		dev_err(device, "request AER IRQ %d failed\n",
+		pci_err(port, "request AER IRQ %d failed\n",
 			dev->irq);
 		return status;
 	}
 
 	aer_enable_rootport(rpc);
-	dev_info(device, "AER enabled with IRQ %d\n", dev->irq);
+	pci_info(port, "AER enabled with IRQ %d\n", dev->irq);
 	return 0;
 }
 
diff --git a/drivers/pci/pcie/aer_inject.c b/drivers/pci/pcie/aer_inject.c
index 95d4759664b3..d4f6d49acd0c 100644
--- a/drivers/pci/pcie/aer_inject.c
+++ b/drivers/pci/pcie/aer_inject.c
@@ -12,6 +12,8 @@
  *     Huang Ying <ying.huang@intel.com>
  */
 
+#define dev_fmt(fmt) "AER: " fmt
+
 #include <linux/module.h>
 #include <linux/init.h>
 #include <linux/irq.h>
@@ -460,12 +462,12 @@ static int aer_inject(struct aer_error_inj *einj)
 	if (device) {
 		edev = to_pcie_device(device);
 		if (!get_service_data(edev)) {
-			dev_warn(&edev->device,
+			pci_warn(edev->port,
 				 "aer_inject: AER service is not initialized\n");
 			ret = -EPROTONOSUPPORT;
 			goto out_put;
 		}
-		dev_info(&edev->device,
+		pci_info(edev->port,
 			 "aer_inject: Injecting errors %08x/%08x into device %s\n",
 			 einj->cor_status, einj->uncor_status, pci_name(dev));
 		local_irq_disable();
-- 
2.17.1

[PATCH v2 6/9] PCI: hotplug: Prefix dmesg logs with PCIe service name

[Frederick Lawler]

Prefix dmesg logs with PCIe service name.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/hotplug/pciehp.h      | 18 +++++++++---------
 drivers/pci/hotplug/pciehp_core.c |  7 +++++--
 drivers/pci/hotplug/pciehp_ctrl.c |  2 ++
 drivers/pci/hotplug/pciehp_hpc.c  |  4 +++-
 drivers/pci/hotplug/pciehp_pci.c  |  2 ++
 5 files changed, 21 insertions(+), 12 deletions(-)

diff --git a/drivers/pci/hotplug/pciehp.h b/drivers/pci/hotplug/pciehp.h
index 506e1d923a1f..78325c8d961e 100644
--- a/drivers/pci/hotplug/pciehp.h
+++ b/drivers/pci/hotplug/pciehp.h
@@ -34,27 +34,27 @@ extern bool pciehp_debug;
 #define dbg(format, arg...)						\
 do {									\
 	if (pciehp_debug)						\
-		printk(KERN_DEBUG "%s: " format, MY_NAME, ## arg);	\
+		pr_info(format, ## arg);				\
 } while (0)
 #define err(format, arg...)						\
-	printk(KERN_ERR "%s: " format, MY_NAME, ## arg)
+	pr_err(format, ## arg)
 #define info(format, arg...)						\
-	printk(KERN_INFO "%s: " format, MY_NAME, ## arg)
+	pr_info(format, ## arg)
 #define warn(format, arg...)						\
-	printk(KERN_WARNING "%s: " format, MY_NAME, ## arg)
+	pr_warn(format, ## arg)
 
 #define ctrl_dbg(ctrl, format, arg...)					\
 	do {								\
 		if (pciehp_debug)					\
-			dev_printk(KERN_DEBUG, &ctrl->pcie->device,	\
-					format, ## arg);		\
+			pci_info(ctrl->pcie->port,			\
+				 format, ## arg);			\
 	} while (0)
 #define ctrl_err(ctrl, format, arg...)					\
-	dev_err(&ctrl->pcie->device, format, ## arg)
+	pci_err(ctrl->pcie->port, format, ## arg)
 #define ctrl_info(ctrl, format, arg...)					\
-	dev_info(&ctrl->pcie->device, format, ## arg)
+	pci_info(ctrl->pcie->port, format, ## arg)
 #define ctrl_warn(ctrl, format, arg...)					\
-	dev_warn(&ctrl->pcie->device, format, ## arg)
+	pci_warn(ctrl->pcie->port, format, ## arg)
 
 #define SLOT_NAME_SIZE 10
 
diff --git a/drivers/pci/hotplug/pciehp_core.c b/drivers/pci/hotplug/pciehp_core.c
index fc5366b50e95..7e06a0f9e644 100644
--- a/drivers/pci/hotplug/pciehp_core.c
+++ b/drivers/pci/hotplug/pciehp_core.c
@@ -17,6 +17,9 @@
  *   Dely Sy <dely.l.sy@intel.com>"
  */
 
+#define pr_fmt(fmt) "pciehp: " fmt
+#define dev_fmt pr_fmt
+
 #include <linux/moduleparam.h>
 #include <linux/kernel.h>
 #include <linux/slab.h>
@@ -182,14 +185,14 @@ static int pciehp_probe(struct pcie_device *dev)
 
 	if (!dev->port->subordinate) {
 		/* Can happen if we run out of bus numbers during probe */
-		dev_err(&dev->device,
+		pci_err(dev->port,
 			"Hotplug bridge without secondary bus, ignoring\n");
 		return -ENODEV;
 	}
 
 	ctrl = pcie_init(dev);
 	if (!ctrl) {
-		dev_err(&dev->device, "Controller initialization failed\n");
+		pci_err(dev->port, "Controller initialization failed\n");
 		return -ENODEV;
 	}
 	set_service_data(dev, ctrl);
diff --git a/drivers/pci/hotplug/pciehp_ctrl.c b/drivers/pci/hotplug/pciehp_ctrl.c
index 3f3df4c29f6e..bf81f977a751 100644
--- a/drivers/pci/hotplug/pciehp_ctrl.c
+++ b/drivers/pci/hotplug/pciehp_ctrl.c
@@ -13,6 +13,8 @@
  *
  */
 
+#define dev_fmt(fmt) "pciehp: " fmt
+
 #include <linux/kernel.h>
 #include <linux/types.h>
 #include <linux/pm_runtime.h>
diff --git a/drivers/pci/hotplug/pciehp_hpc.c b/drivers/pci/hotplug/pciehp_hpc.c
index 6a2365cd794e..1713b0b08a5e 100644
--- a/drivers/pci/hotplug/pciehp_hpc.c
+++ b/drivers/pci/hotplug/pciehp_hpc.c
@@ -12,6 +12,8 @@
  * Send feedback to <greg@kroah.com>,<kristen.c.accardi@intel.com>
  */
 
+#define dev_fmt(fmt) "pciehp: " fmt
+
 #include <linux/kernel.h>
 #include <linux/types.h>
 #include <linux/jiffies.h>
@@ -233,7 +235,7 @@ static bool pci_bus_check_dev(struct pci_bus *bus, int devfn)
 	} while (delay > 0);
 
 	if (count > 1 && pciehp_debug)
-		printk(KERN_DEBUG "pci %04x:%02x:%02x.%d id reading try %d times with interval %d ms to get %08x\n",
+		pr_info("pci %04x:%02x:%02x.%d id reading try %d times with interval %d ms to get %08x\n",
 			pci_domain_nr(bus), bus->number, PCI_SLOT(devfn),
 			PCI_FUNC(devfn), count, step, l);
 
diff --git a/drivers/pci/hotplug/pciehp_pci.c b/drivers/pci/hotplug/pciehp_pci.c
index b9c1396db6fe..d17f3bf36f70 100644
--- a/drivers/pci/hotplug/pciehp_pci.c
+++ b/drivers/pci/hotplug/pciehp_pci.c
@@ -13,6 +13,8 @@
  *
  */
 
+#define dev_fmt(fmt) "pciehp: " fmt
+
 #include <linux/kernel.h>
 #include <linux/types.h>
 #include <linux/pci.h>
-- 
2.17.1

Re: [PATCH v2 6/9] PCI: hotplug: Prefix dmesg logs with PCIe service name

[Bjorn Helgaas]

On Thu, May 02, 2019 at 10:59:43PM -0500, Frederick Lawler wrote:
> Prefix dmesg logs with PCIe service name.
> 
> Signed-off-by: Frederick Lawler <fred@fredlawl.com>
> ---
>  drivers/pci/hotplug/pciehp.h      | 18 +++++++++---------
>  drivers/pci/hotplug/pciehp_core.c |  7 +++++--
>  drivers/pci/hotplug/pciehp_ctrl.c |  2 ++
>  drivers/pci/hotplug/pciehp_hpc.c  |  4 +++-
>  drivers/pci/hotplug/pciehp_pci.c  |  2 ++
>  5 files changed, 21 insertions(+), 12 deletions(-)
> 
> diff --git a/drivers/pci/hotplug/pciehp.h b/drivers/pci/hotplug/pciehp.h
> index 506e1d923a1f..78325c8d961e 100644
> --- a/drivers/pci/hotplug/pciehp.h
> +++ b/drivers/pci/hotplug/pciehp.h
> @@ -34,27 +34,27 @@ extern bool pciehp_debug;
>  #define dbg(format, arg...)						\
>  do {									\
>  	if (pciehp_debug)						\
> -		printk(KERN_DEBUG "%s: " format, MY_NAME, ## arg);	\
> +		pr_info(format, ## arg);				\

This and

>  #define ctrl_dbg(ctrl, format, arg...)					\
>  	do {								\
>  		if (pciehp_debug)					\
> -			dev_printk(KERN_DEBUG, &ctrl->pcie->device,	\
> -					format, ## arg);		\
> +			pci_info(ctrl->pcie->port,			\
> +				 format, ## arg);			\

this are not like the others.  I think replacing the special-purpose
pciehp_debug with the generic dynamic debug thing is a good thing, but
I'd do it in a separate patch, e.g.,

  - if (pciehp_debug)
  -   printk(KERN_DEBUG ...);
  + pr_dbg(...);

And that patch should also remove the pciehp_debug module parameter
and documentation at the same time, of course.

And the commit log should include an example of how to turn on these
messages, boot with "dyndbg='...'".  I don't know what the magic
string there needs to be, so it'd be nice to have it in the commit log
and in a comment near the dbg() and ctrl_dbg() definitions.

>  	} while (0)
>  #define ctrl_err(ctrl, format, arg...)					\
> -	dev_err(&ctrl->pcie->device, format, ## arg)
> +	pci_err(ctrl->pcie->port, format, ## arg)
>  #define ctrl_info(ctrl, format, arg...)					\
> -	dev_info(&ctrl->pcie->device, format, ## arg)
> +	pci_info(ctrl->pcie->port, format, ## arg)
>  #define ctrl_warn(ctrl, format, arg...)					\
> -	dev_warn(&ctrl->pcie->device, format, ## arg)
> +	pci_warn(ctrl->pcie->port, format, ## arg)
>  
>  #define SLOT_NAME_SIZE 10
>  
> diff --git a/drivers/pci/hotplug/pciehp_core.c b/drivers/pci/hotplug/pciehp_core.c
> index fc5366b50e95..7e06a0f9e644 100644
> --- a/drivers/pci/hotplug/pciehp_core.c
> +++ b/drivers/pci/hotplug/pciehp_core.c
> @@ -17,6 +17,9 @@
>   *   Dely Sy <dely.l.sy@intel.com>"
>   */
>  
> +#define pr_fmt(fmt) "pciehp: " fmt
> +#define dev_fmt pr_fmt

Can these go in pciehp.h?

Re: [PATCH v2 6/9] PCI: hotplug: Prefix dmesg logs with PCIe service name

[Andy Shevchenko]

On Fri, May 03, 2019 at 03:04:37PM -0500, Bjorn Helgaas wrote:
> On Thu, May 02, 2019 at 10:59:43PM -0500, Frederick Lawler wrote:

> > +#define pr_fmt(fmt) "pciehp: " fmt
> > +#define dev_fmt pr_fmt
> 
> Can these go in pciehp.h?

In general, no, it can't. The pr_fmt() / dev_fmt() macro must precede any
header inclusion, thus it makes them position dependent.

Otherwise, one has to guarantee above by accurately keeping a header inclusion
ordering.

-- 
With Best Regards,
Andy Shevchenko

[PATCH v2 7/9] PCI: hotplug: Prefer CONFIG_DYNAMIC_DEBUG/DEBUG for dmesg logs

[Frederick Lawler]

dbg() and ctrl_dbg() requires pciehp_debug module parameter to be set
for debug log purposes. There are niche situations in pciehp_hpc.c where
pciehp_debug is used: dbg_ctrl(), and pci_bus_check_dev().

Enabling CONFIG_DYNAMIC_DEBUG/DEBUG is well known for logging debug
information. Therefore, prefer pr/pci_dbg() for debug information, and
reserve pciehp_debug for niche situations.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/hotplug/pciehp.h | 11 ++---------
 1 file changed, 2 insertions(+), 9 deletions(-)

diff --git a/drivers/pci/hotplug/pciehp.h b/drivers/pci/hotplug/pciehp.h
index 78325c8d961e..e852aa478802 100644
--- a/drivers/pci/hotplug/pciehp.h
+++ b/drivers/pci/hotplug/pciehp.h
@@ -32,10 +32,7 @@ extern int pciehp_poll_time;
 extern bool pciehp_debug;
 
 #define dbg(format, arg...)						\
-do {									\
-	if (pciehp_debug)						\
-		pr_info(format, ## arg);				\
-} while (0)
+	pr_debug(format, ## arg);
 #define err(format, arg...)						\
 	pr_err(format, ## arg)
 #define info(format, arg...)						\
@@ -44,11 +41,7 @@ do {									\
 	pr_warn(format, ## arg)
 
 #define ctrl_dbg(ctrl, format, arg...)					\
-	do {								\
-		if (pciehp_debug)					\
-			pci_info(ctrl->pcie->port,			\
-				 format, ## arg);			\
-	} while (0)
+	pci_dbg(ctrl->pcie->port, format, ## arg)
 #define ctrl_err(ctrl, format, arg...)					\
 	pci_err(ctrl->pcie->port, format, ## arg)
 #define ctrl_info(ctrl, format, arg...)					\
-- 
2.17.1

Re: [PATCH v2 7/9] PCI: hotplug: Prefer CONFIG_DYNAMIC_DEBUG/DEBUG for dmesg logs

[Bjorn Helgaas]

On Thu, May 02, 2019 at 10:59:44PM -0500, Frederick Lawler wrote:
> dbg() and ctrl_dbg() requires pciehp_debug module parameter to be set
> for debug log purposes. There are niche situations in pciehp_hpc.c where
> pciehp_debug is used: dbg_ctrl(), and pci_bus_check_dev().
> 
> Enabling CONFIG_DYNAMIC_DEBUG/DEBUG is well known for logging debug
> information. Therefore, prefer pr/pci_dbg() for debug information, and
> reserve pciehp_debug for niche situations.

I guess by "niche situations", you mean the tests in
pci_bus_check_dev() and dbg_ctrl()?

I think pci_bus_check_dev() could skip the test and just use pr_dbg().
For dbg_ctrl(), we could just remove the test (and maybe reformat
those strings so they match other messages).  That's a one-time thing
so I don't think two extra config reads that we might not print are a
problem.

I'd probably reorder these so you have five patches (or maybe more if
I missed something):

  - remove pciehp_debug uses from pci_bus_check_dev() and dbg_ctrl()
  - convert pciehp_debug to dyndbg
  - convert "dev_*(&ctrl->pcie->device)" to "pci_*(ctrl->pcie->port)"
  - add "Slot(%s)" to wrappers (could this be done with dev_fmt?)
  - remove unused wrappers

> Signed-off-by: Frederick Lawler <fred@fredlawl.com>
> ---
>  drivers/pci/hotplug/pciehp.h | 11 ++---------
>  1 file changed, 2 insertions(+), 9 deletions(-)
> 
> diff --git a/drivers/pci/hotplug/pciehp.h b/drivers/pci/hotplug/pciehp.h
> index 78325c8d961e..e852aa478802 100644
> --- a/drivers/pci/hotplug/pciehp.h
> +++ b/drivers/pci/hotplug/pciehp.h
> @@ -32,10 +32,7 @@ extern int pciehp_poll_time;
>  extern bool pciehp_debug;
>  
>  #define dbg(format, arg...)						\
> -do {									\
> -	if (pciehp_debug)						\
> -		pr_info(format, ## arg);				\
> -} while (0)
> +	pr_debug(format, ## arg);
>  #define err(format, arg...)						\
>  	pr_err(format, ## arg)
>  #define info(format, arg...)						\
> @@ -44,11 +41,7 @@ do {									\
>  	pr_warn(format, ## arg)
>  
>  #define ctrl_dbg(ctrl, format, arg...)					\
> -	do {								\
> -		if (pciehp_debug)					\
> -			pci_info(ctrl->pcie->port,			\
> -				 format, ## arg);			\
> -	} while (0)
> +	pci_dbg(ctrl->pcie->port, format, ## arg)
>  #define ctrl_err(ctrl, format, arg...)					\
>  	pci_err(ctrl->pcie->port, format, ## arg)
>  #define ctrl_info(ctrl, format, arg...)					\
> -- 
> 2.17.1
> 

[PATCH v2 8/9] PCI: hotplug: Remove unnecessary dbg/err/info/warn() printk() wrappers

[Frederick Lawler]

Remove unnecessary deb/err/info/warn() printk() wrappers.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/hotplug/pciehp.h      | 9 ---------
 drivers/pci/hotplug/pciehp_core.c | 4 ++--
 2 files changed, 2 insertions(+), 11 deletions(-)

diff --git a/drivers/pci/hotplug/pciehp.h b/drivers/pci/hotplug/pciehp.h
index e852aa478802..06ff9d31405e 100644
--- a/drivers/pci/hotplug/pciehp.h
+++ b/drivers/pci/hotplug/pciehp.h
@@ -31,15 +31,6 @@ extern bool pciehp_poll_mode;
 extern int pciehp_poll_time;
 extern bool pciehp_debug;
 
-#define dbg(format, arg...)						\
-	pr_debug(format, ## arg);
-#define err(format, arg...)						\
-	pr_err(format, ## arg)
-#define info(format, arg...)						\
-	pr_info(format, ## arg)
-#define warn(format, arg...)						\
-	pr_warn(format, ## arg)
-
 #define ctrl_dbg(ctrl, format, arg...)					\
 	pci_dbg(ctrl->pcie->port, format, ## arg)
 #define ctrl_err(ctrl, format, arg...)					\
diff --git a/drivers/pci/hotplug/pciehp_core.c b/drivers/pci/hotplug/pciehp_core.c
index 7e06a0f9e644..67d024b7f476 100644
--- a/drivers/pci/hotplug/pciehp_core.c
+++ b/drivers/pci/hotplug/pciehp_core.c
@@ -331,9 +331,9 @@ int __init pcie_hp_init(void)
 	int retval = 0;
 
 	retval = pcie_port_service_register(&hpdriver_portdrv);
-	dbg("pcie_port_service_register = %d\n", retval);
+	pr_debug("pcie_port_service_register = %d\n", retval);
 	if (retval)
-		dbg("Failure to register service\n");
+		pr_debug("Failure to register service\n");
 
 	return retval;
 }
-- 
2.17.1

[PATCH v2 9/9] PCI: hotplug: Prefix ctrl_*() dmesg logs with pciehp slot name

[Frederick Lawler]

Remove current uses of "Slot(%s)" and then prefix ctrl_*() dmesg
with pciehp slot name to include the slot name for all uses of ctrl_*()
wrappers.

Signed-off-by: Frederick Lawler <fred@fredlawl.com>
---
 drivers/pci/hotplug/pciehp.h      | 12 ++++---
 drivers/pci/hotplug/pciehp_core.c |  9 +++--
 drivers/pci/hotplug/pciehp_ctrl.c | 58 ++++++++++++-------------------
 drivers/pci/hotplug/pciehp_hpc.c  |  5 ++-
 4 files changed, 38 insertions(+), 46 deletions(-)

diff --git a/drivers/pci/hotplug/pciehp.h b/drivers/pci/hotplug/pciehp.h
index 06ff9d31405e..e1cdc3565c62 100644
--- a/drivers/pci/hotplug/pciehp.h
+++ b/drivers/pci/hotplug/pciehp.h
@@ -32,13 +32,17 @@ extern int pciehp_poll_time;
 extern bool pciehp_debug;
 
 #define ctrl_dbg(ctrl, format, arg...)					\
-	pci_dbg(ctrl->pcie->port, format, ## arg)
+	pci_dbg(ctrl->pcie->port, "Slot(%s): " format,			\
+		slot_name(ctrl), ## arg)
 #define ctrl_err(ctrl, format, arg...)					\
-	pci_err(ctrl->pcie->port, format, ## arg)
+	pci_err(ctrl->pcie->port, "Slot(%s): " format,			\
+		slot_name(ctrl), ## arg)
 #define ctrl_info(ctrl, format, arg...)					\
-	pci_info(ctrl->pcie->port, format, ## arg)
+	pci_info(ctrl->pcie->port, "Slot(%s): " format,			\
+		 slot_name(ctrl), ## arg)
 #define ctrl_warn(ctrl, format, arg...)					\
-	pci_warn(ctrl->pcie->port, format, ## arg)
+	pci_warn(ctrl->pcie->port, "Slot(%s): " format,			\
+		 slot_name(ctrl), ## arg)
 
 #define SLOT_NAME_SIZE 10
 
diff --git a/drivers/pci/hotplug/pciehp_core.c b/drivers/pci/hotplug/pciehp_core.c
index 67d024b7f476..ddaa45475572 100644
--- a/drivers/pci/hotplug/pciehp_core.c
+++ b/drivers/pci/hotplug/pciehp_core.c
@@ -85,7 +85,8 @@ static int init_slot(struct controller *ctrl)
 	retval = pci_hp_initialize(&ctrl->hotplug_slot,
 				   ctrl->pcie->port->subordinate, 0, name);
 	if (retval) {
-		ctrl_err(ctrl, "pci_hp_initialize failed: error %d\n", retval);
+		pci_err(ctrl->pcie->port,
+			"pci_hp_initialize failed: error %d\n", retval);
 		kfree(ops);
 	}
 	return retval;
@@ -201,9 +202,11 @@ static int pciehp_probe(struct pcie_device *dev)
 	rc = init_slot(ctrl);
 	if (rc) {
 		if (rc == -EBUSY)
-			ctrl_warn(ctrl, "Slot already registered by another hotplug driver\n");
+			pci_warn(ctrl->pcie->port,
+				 "Slot already registered by another hotplug driver\n");
 		else
-			ctrl_err(ctrl, "Slot initialization failed (%d)\n", rc);
+			pci_err(ctrl->pcie->port,
+				"Slot initialization failed (%d)\n", rc);
 		goto err_out_release_ctlr;
 	}
 
diff --git a/drivers/pci/hotplug/pciehp_ctrl.c b/drivers/pci/hotplug/pciehp_ctrl.c
index bf81f977a751..046ec4d52159 100644
--- a/drivers/pci/hotplug/pciehp_ctrl.c
+++ b/drivers/pci/hotplug/pciehp_ctrl.c
@@ -76,7 +76,7 @@ static int board_added(struct controller *ctrl)
 
 	/* Check for a power fault */
 	if (ctrl->power_fault_detected || pciehp_query_power_fault(ctrl)) {
-		ctrl_err(ctrl, "Slot(%s): Power fault\n", slot_name(ctrl));
+		ctrl_err(ctrl, "Power fault\n");
 		retval = -EIO;
 		goto err_exit;
 	}
@@ -160,12 +160,10 @@ void pciehp_handle_button_press(struct controller *ctrl)
 	case ON_STATE:
 		if (ctrl->state == ON_STATE) {
 			ctrl->state = BLINKINGOFF_STATE;
-			ctrl_info(ctrl, "Slot(%s): Powering off due to button press\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Powering off due to button press\n");
 		} else {
 			ctrl->state = BLINKINGON_STATE;
-			ctrl_info(ctrl, "Slot(%s) Powering on due to button press\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Powering on due to button press\n");
 		}
 		/* blink green LED and turn off amber */
 		pciehp_green_led_blink(ctrl);
@@ -179,7 +177,7 @@ void pciehp_handle_button_press(struct controller *ctrl)
 		 * press the attention again before the 5 sec. limit
 		 * expires to cancel hot-add or hot-remove
 		 */
-		ctrl_info(ctrl, "Slot(%s): Button cancel\n", slot_name(ctrl));
+		ctrl_info(ctrl, "Button cancel\n");
 		cancel_delayed_work(&ctrl->button_work);
 		if (ctrl->state == BLINKINGOFF_STATE) {
 			ctrl->state = ON_STATE;
@@ -189,12 +187,11 @@ void pciehp_handle_button_press(struct controller *ctrl)
 			pciehp_green_led_off(ctrl);
 		}
 		pciehp_set_attention_status(ctrl, 0);
-		ctrl_info(ctrl, "Slot(%s): Action canceled due to button press\n",
-			  slot_name(ctrl));
+		ctrl_info(ctrl, "Action canceled due to button press\n");
 		break;
 	default:
-		ctrl_err(ctrl, "Slot(%s): Ignoring invalid state %#x\n",
-			 slot_name(ctrl), ctrl->state);
+		ctrl_err(ctrl, "Ignoring invalid state %#x\n",
+			 ctrl->state);
 		break;
 	}
 	mutex_unlock(&ctrl->state_lock);
@@ -232,11 +229,9 @@ void pciehp_handle_presence_or_link_change(struct controller *ctrl, u32 events)
 		ctrl->state = POWEROFF_STATE;
 		mutex_unlock(&ctrl->state_lock);
 		if (events & PCI_EXP_SLTSTA_DLLSC)
-			ctrl_info(ctrl, "Slot(%s): Link Down\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Link Down\n");
 		if (events & PCI_EXP_SLTSTA_PDC)
-			ctrl_info(ctrl, "Slot(%s): Card not present\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Card not present\n");
 		pciehp_disable_slot(ctrl, SURPRISE_REMOVAL);
 		break;
 	default:
@@ -261,11 +256,9 @@ void pciehp_handle_presence_or_link_change(struct controller *ctrl, u32 events)
 		ctrl->state = POWERON_STATE;
 		mutex_unlock(&ctrl->state_lock);
 		if (present)
-			ctrl_info(ctrl, "Slot(%s): Card present\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Card present\n");
 		if (link_active)
-			ctrl_info(ctrl, "Slot(%s): Link Up\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Link Up\n");
 		ctrl->request_result = pciehp_enable_slot(ctrl);
 		break;
 	default:
@@ -281,8 +274,7 @@ static int __pciehp_enable_slot(struct controller *ctrl)
 	if (MRL_SENS(ctrl)) {
 		pciehp_get_latch_status(ctrl, &getstatus);
 		if (getstatus) {
-			ctrl_info(ctrl, "Slot(%s): Latch open\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Latch open\n");
 			return -ENODEV;
 		}
 	}
@@ -290,8 +282,7 @@ static int __pciehp_enable_slot(struct controller *ctrl)
 	if (POWER_CTRL(ctrl)) {
 		pciehp_get_power_status(ctrl, &getstatus);
 		if (getstatus) {
-			ctrl_info(ctrl, "Slot(%s): Already enabled\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Already enabled\n");
 			return 0;
 		}
 	}
@@ -323,8 +314,7 @@ static int __pciehp_disable_slot(struct controller *ctrl, bool safe_removal)
 	if (POWER_CTRL(ctrl)) {
 		pciehp_get_power_status(ctrl, &getstatus);
 		if (!getstatus) {
-			ctrl_info(ctrl, "Slot(%s): Already disabled\n",
-				  slot_name(ctrl));
+			ctrl_info(ctrl, "Already disabled\n");
 			return -EINVAL;
 		}
 	}
@@ -367,18 +357,16 @@ int pciehp_sysfs_enable_slot(struct hotplug_slot *hotplug_slot)
 			   !atomic_read(&ctrl->pending_events));
 		return ctrl->request_result;
 	case POWERON_STATE:
-		ctrl_info(ctrl, "Slot(%s): Already in powering on state\n",
-			  slot_name(ctrl));
+		ctrl_info(ctrl, "Already in powering on state\n");
 		break;
 	case BLINKINGOFF_STATE:
 	case ON_STATE:
 	case POWEROFF_STATE:
-		ctrl_info(ctrl, "Slot(%s): Already enabled\n",
-			  slot_name(ctrl));
+		ctrl_info(ctrl, "Already enabled\n");
 		break;
 	default:
-		ctrl_err(ctrl, "Slot(%s): Invalid state %#x\n",
-			 slot_name(ctrl), ctrl->state);
+		ctrl_err(ctrl, "Invalid state %#x\n",
+			 ctrl->state);
 		break;
 	}
 	mutex_unlock(&ctrl->state_lock);
@@ -400,18 +388,16 @@ int pciehp_sysfs_disable_slot(struct hotplug_slot *hotplug_slot)
 			   !atomic_read(&ctrl->pending_events));
 		return ctrl->request_result;
 	case POWEROFF_STATE:
-		ctrl_info(ctrl, "Slot(%s): Already in powering off state\n",
-			  slot_name(ctrl));
+		ctrl_info(ctrl, "Already in powering off state\n");
 		break;
 	case BLINKINGON_STATE:
 	case OFF_STATE:
 	case POWERON_STATE:
-		ctrl_info(ctrl, "Slot(%s): Already disabled\n",
-			  slot_name(ctrl));
+		ctrl_info(ctrl, "Already disabled\n");
 		break;
 	default:
-		ctrl_err(ctrl, "Slot(%s): Invalid state %#x\n",
-			 slot_name(ctrl), ctrl->state);
+		ctrl_err(ctrl, "Invalid state %#x\n",
+			 ctrl->state);
 		break;
 	}
 	mutex_unlock(&ctrl->state_lock);
diff --git a/drivers/pci/hotplug/pciehp_hpc.c b/drivers/pci/hotplug/pciehp_hpc.c
index 1713b0b08a5e..2cb85433736d 100644
--- a/drivers/pci/hotplug/pciehp_hpc.c
+++ b/drivers/pci/hotplug/pciehp_hpc.c
@@ -629,15 +629,14 @@ static irqreturn_t pciehp_ist(int irq, void *dev_id)
 
 	/* Check Attention Button Pressed */
 	if (events & PCI_EXP_SLTSTA_ABP) {
-		ctrl_info(ctrl, "Slot(%s): Attention button pressed\n",
-			  slot_name(ctrl));
+		ctrl_info(ctrl, "Attention button pressed\n");
 		pciehp_handle_button_press(ctrl);
 	}
 
 	/* Check Power Fault Detected */
 	if ((events & PCI_EXP_SLTSTA_PFD) && !ctrl->power_fault_detected) {
 		ctrl->power_fault_detected = 1;
-		ctrl_err(ctrl, "Slot(%s): Power fault\n", slot_name(ctrl));
+		ctrl_err(ctrl, "Power fault\n");
 		pciehp_set_attention_status(ctrl, 1);
 		pciehp_green_led_off(ctrl);
 	}
-- 
2.17.1

Re: [PATCH v2 9/9] PCI: hotplug: Prefix ctrl_*() dmesg logs with pciehp slot name

[Bjorn Helgaas]

On Thu, May 02, 2019 at 10:59:46PM -0500, Frederick Lawler wrote:
> Remove current uses of "Slot(%s)" and then prefix ctrl_*() dmesg
> with pciehp slot name to include the slot name for all uses of ctrl_*()
> wrappers.
> 
> Signed-off-by: Frederick Lawler <fred@fredlawl.com>
> ---
>  drivers/pci/hotplug/pciehp.h      | 12 ++++---
>  drivers/pci/hotplug/pciehp_core.c |  9 +++--
>  drivers/pci/hotplug/pciehp_ctrl.c | 58 ++++++++++++-------------------
>  drivers/pci/hotplug/pciehp_hpc.c  |  5 ++-
>  4 files changed, 38 insertions(+), 46 deletions(-)
> 
> diff --git a/drivers/pci/hotplug/pciehp.h b/drivers/pci/hotplug/pciehp.h
> index 06ff9d31405e..e1cdc3565c62 100644
> --- a/drivers/pci/hotplug/pciehp.h
> +++ b/drivers/pci/hotplug/pciehp.h
> @@ -32,13 +32,17 @@ extern int pciehp_poll_time;
>  extern bool pciehp_debug;
>  
>  #define ctrl_dbg(ctrl, format, arg...)					\
> -	pci_dbg(ctrl->pcie->port, format, ## arg)
> +	pci_dbg(ctrl->pcie->port, "Slot(%s): " format,			\
> +		slot_name(ctrl), ## arg)

This would be nice to do, but given the current code organization, I don't
think it's actually feasible to use slot_name() in these wrappers because
the slot name is initialized in init_slot(), but there are lots of places
we can emit messages before that, especially if debug is enabled:

  pciehp_probe
    pcie_init
      dbg_ctrl
        ctrl_info                          # no slot yet
      ctrl_info("Slot #%d AttnBtn%c ...")  # no slot yet
      if (POWER_CTRL)
        pciehp_get_power_status
	  ctrl_dbg("SLOTCTRL")             # no slot yet
	if (...)
	  pcie_disable_notification
	    pcie_write_cmd
	      pcie_do_write_cmd
	        ctrl_info("no response")   # no slot yet
	    ctrl_dbg("SLOTCTRL")           # no slot yet
	  pciehp_power_off_slot
	    ctrl_dbg("SLOTCTRL")           # no slot yet
    init_slot                              # slot valid after this returns