[PATCH v3 0/4] ACPI: hotplug messages improvement

[PATCH v3 0/4] ACPI: hotplug messages improvement

[Toshi Kani]

This patchset improves logging messages for ACPI CPU, Memory, and
Container hotplug notify handlers.  The patchset introduces a set of
new macro interfaces, acpi_pr_<level>(), and updates the notify
handlers to use them.  acpi_pr_<level>() appends "ACPI" prefix and
ACPI object path to the messages, and its usage model is similar to
dev_<level>().  This improves diagnostics in hotplug operations
since it identifies an object that caused an issue in a log file.

v3:
 - Changed acpi_pr_debug() to NOP when !DEBUG and !DYNAMIC_DEBUG.
   DYNAMIC_DEBUG will be supported later.
 - Added const to a path variable in acpi_printk().
 - Added more descriptions to the change log of patch 1/4.

v2:
 - Set buffer.pointer to NULL in acpi_printk().
 - Added acpi_pr_debug().

---
This patchset applies on top of the patch below.

[PATCH] ACPI: Add ACPI CPU hot-remove support
http://marc.info/?l=linux-acpi&m=134098193327362&w=2

---
Toshi Kani (4):
 ACPI: Add acpi_pr_<level>() interfaces
 ACPI: Update CPU hotplug messages
 ACPI: Update Memory hotplug messages
 ACPI: Update Container hotplug messages

---
 drivers/acpi/acpi_memhotplug.c  |   24 ++++++++++++------------
 drivers/acpi/container.c        |    6 +++---
 drivers/acpi/processor_driver.c |   36 +++++++++++++++++++++---------------
 drivers/acpi/utils.c            |   34 ++++++++++++++++++++++++++++++++++
 include/acpi/acpi_bus.h         |   31 +++++++++++++++++++++++++++++++
 5 files changed, 101 insertions(+), 30 deletions(-)

[PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Toshi Kani]

This patch introduces acpi_pr_<level>(), where <level> is a kernel
message level such as err/warn/info, to support improved logging
messages for ACPI, esp. in hotplug operations.  acpi_pr_<level>()
appends "ACPI" prefix and ACPI object path to the messages.  This
improves diagnostics in hotplug operations since it identifies an
object that caused an issue in a log file.

acpi_pr_<level>() takes acpi_handle as an argument, which is passed
to ACPI hotplug notify handlers from the ACPICA.  Therefore, it is
always available unlike other kernel objects, such as device.

For example, the statement below
  acpi_pr_err(handle, "Device don't exist, dropping EJECT\n");
logs an error message like this at KERN_ERR.
  ACPI: \_SB_.SCK4.CPU4: Device don't exist, dropping EJECT

ACPI drivers can use acpi_pr_<level>() when they need to identify
a target ACPI object in their messages, such as error messages.
The usage model is similar to dev_<level>().  acpi_pr_<level>() can
be used when device is not created/valid, which may be the case for
ACPI hotplug handlers.  ACPI drivers can continue to use dev_<level>()
when device is valid.

ACPI drivers also continue to use pr_<level>() when ACPI device
path does not have to be appended to the messages, such as boot-up
messages.

Note: ACPI_[WARNING|INFO|ERROR]() are intended for the ACPICA and
are not associated with the kernel message level.

Signed-off-by: Toshi Kani <toshi.kani@hp.com>
Tested-by: Vijay Mohan Pandarathil <vijaymohan.pandarathil@hp.com>
---
 drivers/acpi/utils.c    |   34 ++++++++++++++++++++++++++++++++++
 include/acpi/acpi_bus.h |   31 +++++++++++++++++++++++++++++++
 2 files changed, 65 insertions(+), 0 deletions(-)

diff --git a/drivers/acpi/utils.c b/drivers/acpi/utils.c
index 3e87c9c..ec0c6f9 100644
--- a/drivers/acpi/utils.c
+++ b/drivers/acpi/utils.c
@@ -454,3 +454,37 @@ acpi_evaluate_hotplug_ost(acpi_handle handle, u32 source_event,
 #endif
 }
 EXPORT_SYMBOL(acpi_evaluate_hotplug_ost);
+
+/**
+ * acpi_printk: Print messages with ACPI prefix and object path
+ *
+ * This function is intended to be called through acpi_pr_<level> macros.
+ */
+void
+acpi_printk(const char *level, acpi_handle handle, const char *fmt, ...)
+{
+	struct va_format vaf;
+	va_list args;
+	struct acpi_buffer buffer = {
+		.length = ACPI_ALLOCATE_BUFFER,
+		.pointer = NULL
+	};
+	const char *path;
+	acpi_status ret;
+
+	va_start(args, fmt);
+	vaf.fmt = fmt;
+	vaf.va = &args;
+
+	ret = acpi_get_name(handle, ACPI_FULL_PATHNAME, &buffer);
+	if (ret == AE_OK)
+		path = buffer.pointer;
+	else
+		path = "<n/a>";
+
+	printk("%sACPI: %s: %pV", level, path, &vaf);
+
+	va_end(args);
+	kfree(buffer.pointer);
+}
+EXPORT_SYMBOL(acpi_printk);
diff --git a/include/acpi/acpi_bus.h b/include/acpi/acpi_bus.h
index bde976e..1c855b8 100644
--- a/include/acpi/acpi_bus.h
+++ b/include/acpi/acpi_bus.h
@@ -85,6 +85,37 @@ struct acpi_pld {
 
 acpi_status
 acpi_get_physical_device_location(acpi_handle handle, struct acpi_pld *pld);
+
+void acpi_printk(const char *level, acpi_handle handle, const char *fmt, ...);
+
+#define acpi_pr_emerg(handle, fmt, ...)				\
+	acpi_printk(KERN_EMERG, handle, fmt, ##__VA_ARGS__)
+#define acpi_pr_alert(handle, fmt, ...)				\
+	acpi_printk(KERN_ALERT, handle, fmt, ##__VA_ARGS__)
+#define acpi_pr_crit(handle, fmt, ...)				\
+	acpi_printk(KERN_CRIT, handle, fmt, ##__VA_ARGS__)
+#define acpi_pr_err(handle, fmt, ...)				\
+	acpi_printk(KERN_ERR, handle, fmt, ##__VA_ARGS__)
+#define acpi_pr_warn(handle, fmt, ...)				\
+	acpi_printk(KERN_WARNING, handle, fmt, ##__VA_ARGS__)
+#define acpi_pr_notice(handle, fmt, ...)			\
+	acpi_printk(KERN_NOTICE, handle, fmt, ##__VA_ARGS__)
+#define acpi_pr_info(handle, fmt, ...)				\
+	acpi_printk(KERN_INFO, handle, fmt, ##__VA_ARGS__)
+
+/* REVISIT: Need to support CONFIG_DYNAMIC_DEBUG */
+#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)
+#define acpi_pr_debug(handle, fmt, ...)					\
+	acpi_printk(KERN_DEBUG, handle, fmt, ##__VA_ARGS__)
+#else
+#define acpi_pr_debug(handle, fmt, ...)					\
+({									\
+	if (0)								\
+		acpi_printk(KERN_DEBUG, handle, fmt, ##__VA_ARGS__);	\
+	0;								\
+})
+#endif
+
 #ifdef CONFIG_ACPI
 
 #include <linux/proc_fs.h>
-- 
1.7.7.6

[PATCH v3 2/4] ACPI: Update CPU hotplug messages

[Toshi Kani]

Updated CPU hotplug log messages with acpi_pr_<level>(),
dev_<level>() and pr_<level>().  Some messages are also
changed for clarity.

Signed-off-by: Toshi Kani <toshi.kani@hp.com>
Tested-by: Vijay Mohan Pandarathil <vijaymohan.pandarathil@hp.com>
---
 drivers/acpi/processor_driver.c |   36 +++++++++++++++++++++---------------
 1 files changed, 21 insertions(+), 15 deletions(-)

diff --git a/drivers/acpi/processor_driver.c b/drivers/acpi/processor_driver.c
index a6bdeaa..225f252 100644
--- a/drivers/acpi/processor_driver.c
+++ b/drivers/acpi/processor_driver.c
@@ -282,7 +282,9 @@ static int acpi_processor_get_info(struct acpi_device *device)
 		/* Declared with "Processor" statement; match ProcessorID */
 		status = acpi_evaluate_object(pr->handle, NULL, NULL, &buffer);
 		if (ACPI_FAILURE(status)) {
-			printk(KERN_ERR PREFIX "Evaluating processor object\n");
+			acpi_pr_err(pr->handle,
+				"Failed to evaluate processor object (0x%x)\n",
+				status);
 			return -ENODEV;
 		}
 
@@ -301,8 +303,9 @@ static int acpi_processor_get_info(struct acpi_device *device)
 		status = acpi_evaluate_integer(pr->handle, METHOD_NAME__UID,
 						NULL, &value);
 		if (ACPI_FAILURE(status)) {
-			printk(KERN_ERR PREFIX
-			    "Evaluating processor _UID [%#x]\n", status);
+			acpi_pr_err(pr->handle,
+				"Failed to evaluate processor _UID (0x%x)\n",
+				status);
 			return -ENODEV;
 		}
 		device_declaration = 1;
@@ -345,7 +348,7 @@ static int acpi_processor_get_info(struct acpi_device *device)
 	if (!object.processor.pblk_address)
 		ACPI_DEBUG_PRINT((ACPI_DB_INFO, "No PBLK (NULL address)\n"));
 	else if (object.processor.pblk_length != 6)
-		printk(KERN_ERR PREFIX "Invalid PBLK length [%d]\n",
+		acpi_pr_err(pr->handle, "Invalid PBLK length [%d]\n",
 			    object.processor.pblk_length);
 	else {
 		pr->throttling.address = object.processor.pblk_address;
@@ -429,8 +432,8 @@ static int acpi_cpu_soft_notify(struct notifier_block *nfb,
 		 * Initialize missing things
 		 */
 		if (pr->flags.need_hotplug_init) {
-			printk(KERN_INFO "Will online and init hotplugged "
-			       "CPU: %d\n", pr->id);
+			pr_info("Will online and init hotplugged CPU: %d\n",
+				pr->id);
 			WARN(acpi_processor_start(pr), "Failed to start CPU:"
 				" %d\n", pr->id);
 			pr->flags.need_hotplug_init = 0;
@@ -491,14 +494,16 @@ static __ref int acpi_processor_start(struct acpi_processor *pr)
 				   &pr->cdev->device.kobj,
 				   "thermal_cooling");
 	if (result) {
-		printk(KERN_ERR PREFIX "Create sysfs link\n");
+		dev_err(&device->dev,
+			"Failed to create sysfs link 'thermal_cooling'\n");
 		goto err_thermal_unregister;
 	}
 	result = sysfs_create_link(&pr->cdev->device.kobj,
 				   &device->dev.kobj,
 				   "device");
 	if (result) {
-		printk(KERN_ERR PREFIX "Create sysfs link\n");
+		dev_err(&pr->cdev->device,
+			"Failed to create sysfs link 'device'\n");
 		goto err_remove_sysfs_thermal;
 	}
 
@@ -560,8 +565,7 @@ static int __cpuinit acpi_processor_add(struct acpi_device *device)
 	 */
 	if (per_cpu(processor_device_array, pr->id) != NULL &&
 	    per_cpu(processor_device_array, pr->id) != device) {
-		printk(KERN_WARNING "BIOS reported wrong ACPI id "
-			"for the processor\n");
+		pr_warn("BIOS reported wrong ACPI id for the processor\n");
 		result = -ENODEV;
 		goto err_free_cpumask;
 	}
@@ -715,7 +719,7 @@ static void acpi_processor_hotplug_notify(acpi_handle handle,
 
 		result = acpi_processor_device_add(handle, &device);
 		if (result) {
-			pr_err(PREFIX "Unable to add the device\n");
+			acpi_pr_err(handle, "Unable to add the device\n");
 			break;
 		}
 
@@ -727,17 +731,19 @@ static void acpi_processor_hotplug_notify(acpi_handle handle,
 				  "received ACPI_NOTIFY_EJECT_REQUEST\n"));
 
 		if (acpi_bus_get_device(handle, &device)) {
-			pr_err(PREFIX "Device don't exist, dropping EJECT\n");
+			acpi_pr_err(handle,
+				"Device don't exist, dropping EJECT\n");
 			break;
 		}
 		if (!acpi_driver_data(device)) {
-			pr_err(PREFIX "Driver data is NULL, dropping EJECT\n");
+			acpi_pr_err(handle,
+				"Driver data is NULL, dropping EJECT\n");
 			break;
 		}
 
 		ej_event = kmalloc(sizeof(*ej_event), GFP_KERNEL);
 		if (!ej_event) {
-			pr_err(PREFIX "No memory, dropping EJECT\n");
+			acpi_pr_err(handle, "No memory, dropping EJECT\n");
 			break;
 		}
 
@@ -847,7 +853,7 @@ static acpi_status acpi_processor_hotadd_init(struct acpi_processor *pr)
 	 * and do it when the CPU gets online the first time
 	 * TBD: Cleanup above functions and try to do this more elegant.
 	 */
-	printk(KERN_INFO "CPU %d got hotplugged\n", pr->id);
+	pr_info("CPU %d got hotplugged\n", pr->id);
 	pr->flags.need_hotplug_init = 1;
 
 	return AE_OK;
-- 
1.7.7.6

[PATCH v3 3/4] ACPI: Update Memory hotplug messages

[Toshi Kani]

Updated Memory hotplug log messages with acpi_pr_<level>()
and pr_<level>().

Signed-off-by: Toshi Kani <toshi.kani@hp.com>
---
 drivers/acpi/acpi_memhotplug.c |   24 ++++++++++++------------
 1 files changed, 12 insertions(+), 12 deletions(-)

diff --git a/drivers/acpi/acpi_memhotplug.c b/drivers/acpi/acpi_memhotplug.c
index 06c55cd..dcc8f4d 100644
--- a/drivers/acpi/acpi_memhotplug.c
+++ b/drivers/acpi/acpi_memhotplug.c
@@ -170,7 +170,7 @@ acpi_memory_get_device(acpi_handle handle,
 	/* Get the parent device */
 	result = acpi_bus_get_device(phandle, &pdevice);
 	if (result) {
-		printk(KERN_WARNING PREFIX "Cannot get acpi bus device");
+		acpi_pr_warn(phandle, "Cannot get acpi bus device\n");
 		return -EINVAL;
 	}
 
@@ -180,14 +180,14 @@ acpi_memory_get_device(acpi_handle handle,
 	 */
 	result = acpi_bus_add(&device, pdevice, handle, ACPI_BUS_TYPE_DEVICE);
 	if (result) {
-		printk(KERN_WARNING PREFIX "Cannot add acpi bus");
+		acpi_pr_warn(handle, "Cannot add acpi bus\n");
 		return -EINVAL;
 	}
 
       end:
 	*mem_device = acpi_driver_data(device);
 	if (!(*mem_device)) {
-		printk(KERN_ERR "\n driver data not found");
+		acpi_pr_err(handle, "driver data not found\n");
 		return -ENODEV;
 	}
 
@@ -224,7 +224,7 @@ static int acpi_memory_enable_device(struct acpi_memory_device *mem_device)
 	/* Get the range from the _CRS */
 	result = acpi_memory_get_device_resources(mem_device);
 	if (result) {
-		printk(KERN_ERR PREFIX "get_device_resources failed\n");
+		pr_err(PREFIX "get_device_resources failed\n");
 		mem_device->state = MEMORY_INVALID_STATE;
 		return result;
 	}
@@ -257,7 +257,7 @@ static int acpi_memory_enable_device(struct acpi_memory_device *mem_device)
 		num_enabled++;
 	}
 	if (!num_enabled) {
-		printk(KERN_ERR PREFIX "add_memory failed\n");
+		acpi_pr_err(mem_device->device->handle, "add_memory failed\n");
 		mem_device->state = MEMORY_INVALID_STATE;
 		return -EINVAL;
 	}
@@ -353,7 +353,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
 			ACPI_DEBUG_PRINT((ACPI_DB_INFO,
 					  "\nReceived DEVICE CHECK notification for device\n"));
 		if (acpi_memory_get_device(handle, &mem_device)) {
-			printk(KERN_ERR PREFIX "Cannot find driver data\n");
+			acpi_pr_err(handle, "Cannot find driver data\n");
 			break;
 		}
 
@@ -361,7 +361,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
 			break;
 
 		if (acpi_memory_enable_device(mem_device)) {
-			pr_err(PREFIX "Cannot enable memory device\n");
+			acpi_pr_err(handle, "Cannot enable memory device\n");
 			break;
 		}
 
@@ -373,12 +373,12 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
 				  "\nReceived EJECT REQUEST notification for device\n"));
 
 		if (acpi_bus_get_device(handle, &device)) {
-			printk(KERN_ERR PREFIX "Device doesn't exist\n");
+			acpi_pr_err(handle, "Device doesn't exist\n");
 			break;
 		}
 		mem_device = acpi_driver_data(device);
 		if (!mem_device) {
-			printk(KERN_ERR PREFIX "Driver Data is NULL\n");
+			acpi_pr_err(handle, "Driver Data is NULL\n");
 			break;
 		}
 
@@ -389,7 +389,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
 		 *      with generic sysfs driver
 		 */
 		if (acpi_memory_disable_device(mem_device)) {
-			pr_err(PREFIX "Disable memory device\n");
+			acpi_pr_err(handle, "Disable memory device\n");
 			/*
 			 * If _EJ0 was called but failed, _OST is not
 			 * necessary.
@@ -449,7 +449,7 @@ static int acpi_memory_device_add(struct acpi_device *device)
 	/* Set the device state */
 	mem_device->state = MEMORY_POWER_ON_STATE;
 
-	printk(KERN_DEBUG "%s \n", acpi_device_name(device));
+	pr_debug("%s\n", acpi_device_name(device));
 
 	/*
 	 * Early boot code has recognized memory area by EFI/E820.
@@ -464,7 +464,7 @@ static int acpi_memory_device_add(struct acpi_device *device)
 		/* call add_memory func */
 		result = acpi_memory_enable_device(mem_device);
 		if (result)
-			printk(KERN_ERR PREFIX
+			acpi_pr_err(device->handle,
 				"Error in acpi_memory_enable_device\n");
 	}
 	return result;
-- 
1.7.7.6

[PATCH v3 4/4] ACPI: Update Container hotplug messages

[Toshi Kani]

Updated Container hotplug log messages with acpi_pr_<level>()
and pr_<level>().

Signed-off-by: Toshi Kani <toshi.kani@hp.com>
---
 drivers/acpi/container.c |    6 +++---
 1 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/drivers/acpi/container.c b/drivers/acpi/container.c
index 01a986d..643e962 100644
--- a/drivers/acpi/container.c
+++ b/drivers/acpi/container.c
@@ -99,7 +99,7 @@ static int acpi_container_add(struct acpi_device *device)
 
 
 	if (!device) {
-		printk(KERN_ERR PREFIX "device is NULL\n");
+		pr_err(PREFIX "device is NULL\n");
 		return -EINVAL;
 	}
 
@@ -164,7 +164,7 @@ static void container_notify_cb(acpi_handle handle, u32 type, void *context)
 	case ACPI_NOTIFY_BUS_CHECK:
 		/* Fall through */
 	case ACPI_NOTIFY_DEVICE_CHECK:
-		printk(KERN_WARNING "Container driver received %s event\n",
+		pr_warn("Container driver received %s event\n",
 		       (type == ACPI_NOTIFY_BUS_CHECK) ?
 		       "ACPI_NOTIFY_BUS_CHECK" : "ACPI_NOTIFY_DEVICE_CHECK");
 
@@ -185,7 +185,7 @@ static void container_notify_cb(acpi_handle handle, u32 type, void *context)
 
 		result = container_device_add(&device, handle);
 		if (result) {
-			pr_warn("Failed to add container\n");
+			acpi_pr_warn(handle, "Failed to add container\n");
 			break;
 		}
 
-- 
1.7.7.6

Re: [PATCH v3 0/4] ACPI: hotplug messages improvement

[Joe Perches]

On Wed, 2012-07-25 at 17:12 -0600, Toshi Kani wrote:
> This patchset improves logging messages for ACPI CPU, Memory, and
> Container hotplug notify handlers.  The patchset introduces a set of
> new macro interfaces, acpi_pr_<level>(), and updates the notify
> handlers to use them.  acpi_pr_<level>() appends "ACPI" prefix and
> ACPI object path to the messages, and its usage model is similar to
> dev_<level>().  This improves diagnostics in hotplug operations
> since it identifies an object that caused an issue in a log file.
> 
> v3:
>  - Changed acpi_pr_debug() to NOP when !DEBUG and !DYNAMIC_DEBUG.
>    DYNAMIC_DEBUG will be supported later.
>  - Added const to a path variable in acpi_printk().
>  - Added more descriptions to the change log of patch 1/4.

Thanks Toshi.

This seems sensible to me.  I've no more comments either.

Re: [PATCH v3 0/4] ACPI: hotplug messages improvement

[Toshi Kani]

On Wed, 2012-07-25 at 16:31 -0700, Joe Perches wrote:
> On Wed, 2012-07-25 at 17:12 -0600, Toshi Kani wrote:
> > This patchset improves logging messages for ACPI CPU, Memory, and
> > Container hotplug notify handlers.  The patchset introduces a set of
> > new macro interfaces, acpi_pr_<level>(), and updates the notify
> > handlers to use them.  acpi_pr_<level>() appends "ACPI" prefix and
> > ACPI object path to the messages, and its usage model is similar to
> > dev_<level>().  This improves diagnostics in hotplug operations
> > since it identifies an object that caused an issue in a log file.
> > 
> > v3:
> >  - Changed acpi_pr_debug() to NOP when !DEBUG and !DYNAMIC_DEBUG.
> >    DYNAMIC_DEBUG will be supported later.
> >  - Added const to a path variable in acpi_printk().
> >  - Added more descriptions to the change log of patch 1/4.
> 
> Thanks Toshi.
> 
> This seems sensible to me.  I've no more comments either.

Thanks Joe for the valuable suggestions!
-Toshi

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Bjorn Helgaas]

On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> This patch introduces acpi_pr_<level>(), where <level> is a kernel
> message level such as err/warn/info, to support improved logging
> messages for ACPI, esp. in hotplug operations.  acpi_pr_<level>()
> appends "ACPI" prefix and ACPI object path to the messages.  This
> improves diagnostics in hotplug operations since it identifies an
> object that caused an issue in a log file.
>
> acpi_pr_<level>() takes acpi_handle as an argument, which is passed
> to ACPI hotplug notify handlers from the ACPICA.  Therefore, it is
> always available unlike other kernel objects, such as device.
>
> For example, the statement below
>   acpi_pr_err(handle, "Device don't exist, dropping EJECT\n");
> logs an error message like this at KERN_ERR.
>   ACPI: \_SB_.SCK4.CPU4: Device don't exist, dropping EJECT
>
> ACPI drivers can use acpi_pr_<level>() when they need to identify
> a target ACPI object in their messages, such as error messages.

It's definitely an improvement to have *something* that identifies a
device in these messages.  But the ACPI namespace path is not really
intended to be user-consumable, so I don't think we should expose it
indiscriminately.  I think we should be using the ACPI device name
("PNP0C02:00") whenever possible.  Given the device name, we can get
the path from the sysfs "path" file.

> The usage model is similar to dev_<level>().  acpi_pr_<level>() can
> be used when device is not created/valid, which may be the case for
> ACPI hotplug handlers.  ACPI drivers can continue to use dev_<level>()
> when device is valid.

I'd argue that ACPI driver code should never be called unless the
device is valid, so drivers should *always* be able to use
dev_<level>.  Obviously, ACPI hotplug is currently screwed up (it's
mostly handled in drivers rather than in the ACPI core), so in some of
those hotplug paths in the drivers, we may not have a device yet.  But
those cases should be minimal.

Another possible approach to this is to add a %p extension rather than
adding acpi_printk().  Then you could do, e.g., 'printk("%pA ...\n",
handle)', and printk could interpolate the namespace path.  But I
really think there should be very few places where we need the path,
so I'm not sure it's worth it.

> ACPI drivers also continue to use pr_<level>() when ACPI device
> path does not have to be appended to the messages, such as boot-up
> messages.
>
> Note: ACPI_[WARNING|INFO|ERROR]() are intended for the ACPICA and
> are not associated with the kernel message level.
>
> Signed-off-by: Toshi Kani <toshi.kani@hp.com>
> Tested-by: Vijay Mohan Pandarathil <vijaymohan.pandarathil@hp.com>
> ---
>  drivers/acpi/utils.c    |   34 ++++++++++++++++++++++++++++++++++
>  include/acpi/acpi_bus.h |   31 +++++++++++++++++++++++++++++++
>  2 files changed, 65 insertions(+), 0 deletions(-)
>
> diff --git a/drivers/acpi/utils.c b/drivers/acpi/utils.c
> index 3e87c9c..ec0c6f9 100644
> --- a/drivers/acpi/utils.c
> +++ b/drivers/acpi/utils.c
> @@ -454,3 +454,37 @@ acpi_evaluate_hotplug_ost(acpi_handle handle, u32 source_event,
>  #endif
>  }
>  EXPORT_SYMBOL(acpi_evaluate_hotplug_ost);
> +
> +/**
> + * acpi_printk: Print messages with ACPI prefix and object path
> + *
> + * This function is intended to be called through acpi_pr_<level> macros.
> + */
> +void
> +acpi_printk(const char *level, acpi_handle handle, const char *fmt, ...)
> +{
> +       struct va_format vaf;
> +       va_list args;
> +       struct acpi_buffer buffer = {
> +               .length = ACPI_ALLOCATE_BUFFER,
> +               .pointer = NULL
> +       };
> +       const char *path;
> +       acpi_status ret;
> +
> +       va_start(args, fmt);
> +       vaf.fmt = fmt;
> +       vaf.va = &args;
> +
> +       ret = acpi_get_name(handle, ACPI_FULL_PATHNAME, &buffer);
> +       if (ret == AE_OK)
> +               path = buffer.pointer;
> +       else
> +               path = "<n/a>";
> +
> +       printk("%sACPI: %s: %pV", level, path, &vaf);
> +
> +       va_end(args);
> +       kfree(buffer.pointer);
> +}
> +EXPORT_SYMBOL(acpi_printk);
> diff --git a/include/acpi/acpi_bus.h b/include/acpi/acpi_bus.h
> index bde976e..1c855b8 100644
> --- a/include/acpi/acpi_bus.h
> +++ b/include/acpi/acpi_bus.h
> @@ -85,6 +85,37 @@ struct acpi_pld {
>
>  acpi_status
>  acpi_get_physical_device_location(acpi_handle handle, struct acpi_pld *pld);
> +
> +void acpi_printk(const char *level, acpi_handle handle, const char *fmt, ...);
> +
> +#define acpi_pr_emerg(handle, fmt, ...)                                \
> +       acpi_printk(KERN_EMERG, handle, fmt, ##__VA_ARGS__)
> +#define acpi_pr_alert(handle, fmt, ...)                                \
> +       acpi_printk(KERN_ALERT, handle, fmt, ##__VA_ARGS__)
> +#define acpi_pr_crit(handle, fmt, ...)                         \
> +       acpi_printk(KERN_CRIT, handle, fmt, ##__VA_ARGS__)
> +#define acpi_pr_err(handle, fmt, ...)                          \
> +       acpi_printk(KERN_ERR, handle, fmt, ##__VA_ARGS__)
> +#define acpi_pr_warn(handle, fmt, ...)                         \
> +       acpi_printk(KERN_WARNING, handle, fmt, ##__VA_ARGS__)
> +#define acpi_pr_notice(handle, fmt, ...)                       \
> +       acpi_printk(KERN_NOTICE, handle, fmt, ##__VA_ARGS__)
> +#define acpi_pr_info(handle, fmt, ...)                         \
> +       acpi_printk(KERN_INFO, handle, fmt, ##__VA_ARGS__)
> +
> +/* REVISIT: Need to support CONFIG_DYNAMIC_DEBUG */
> +#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)
> +#define acpi_pr_debug(handle, fmt, ...)                                        \
> +       acpi_printk(KERN_DEBUG, handle, fmt, ##__VA_ARGS__)
> +#else
> +#define acpi_pr_debug(handle, fmt, ...)                                        \
> +({                                                                     \
> +       if (0)                                                          \
> +               acpi_printk(KERN_DEBUG, handle, fmt, ##__VA_ARGS__);    \
> +       0;                                                              \
> +})
> +#endif
> +
>  #ifdef CONFIG_ACPI
>
>  #include <linux/proc_fs.h>
> --
> 1.7.7.6
>

Re: [PATCH v3 2/4] ACPI: Update CPU hotplug messages

[Bjorn Helgaas]

On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> Updated CPU hotplug log messages with acpi_pr_<level>(),
> dev_<level>() and pr_<level>().  Some messages are also
> changed for clarity.
>
> Signed-off-by: Toshi Kani <toshi.kani@hp.com>
> Tested-by: Vijay Mohan Pandarathil <vijaymohan.pandarathil@hp.com>
> ---
>  drivers/acpi/processor_driver.c |   36 +++++++++++++++++++++---------------
>  1 files changed, 21 insertions(+), 15 deletions(-)
>
> diff --git a/drivers/acpi/processor_driver.c b/drivers/acpi/processor_driver.c
> index a6bdeaa..225f252 100644
> --- a/drivers/acpi/processor_driver.c
> +++ b/drivers/acpi/processor_driver.c
> @@ -282,7 +282,9 @@ static int acpi_processor_get_info(struct acpi_device *device)
>                 /* Declared with "Processor" statement; match ProcessorID */
>                 status = acpi_evaluate_object(pr->handle, NULL, NULL, &buffer);
>                 if (ACPI_FAILURE(status)) {
> -                       printk(KERN_ERR PREFIX "Evaluating processor object\n");
> +                       acpi_pr_err(pr->handle,
> +                               "Failed to evaluate processor object (0x%x)\n",
> +                               status);

This looks like it could be a dev_err().

>                         return -ENODEV;
>                 }
>
> @@ -301,8 +303,9 @@ static int acpi_processor_get_info(struct acpi_device *device)
>                 status = acpi_evaluate_integer(pr->handle, METHOD_NAME__UID,
>                                                 NULL, &value);
>                 if (ACPI_FAILURE(status)) {
> -                       printk(KERN_ERR PREFIX
> -                           "Evaluating processor _UID [%#x]\n", status);
> +                       acpi_pr_err(pr->handle,
> +                               "Failed to evaluate processor _UID (0x%x)\n",
> +                               status);

And this.

>                         return -ENODEV;
>                 }
>                 device_declaration = 1;
> @@ -345,7 +348,7 @@ static int acpi_processor_get_info(struct acpi_device *device)
>         if (!object.processor.pblk_address)
>                 ACPI_DEBUG_PRINT((ACPI_DB_INFO, "No PBLK (NULL address)\n"));
>         else if (object.processor.pblk_length != 6)
> -               printk(KERN_ERR PREFIX "Invalid PBLK length [%d]\n",
> +               acpi_pr_err(pr->handle, "Invalid PBLK length [%d]\n",

And this.

>                             object.processor.pblk_length);
>         else {
>                 pr->throttling.address = object.processor.pblk_address;
> @@ -429,8 +432,8 @@ static int acpi_cpu_soft_notify(struct notifier_block *nfb,
>                  * Initialize missing things
>                  */
>                 if (pr->flags.need_hotplug_init) {
> -                       printk(KERN_INFO "Will online and init hotplugged "
> -                              "CPU: %d\n", pr->id);
> +                       pr_info("Will online and init hotplugged CPU: %d\n",
> +                               pr->id);
>                         WARN(acpi_processor_start(pr), "Failed to start CPU:"
>                                 " %d\n", pr->id);
>                         pr->flags.need_hotplug_init = 0;
> @@ -491,14 +494,16 @@ static __ref int acpi_processor_start(struct acpi_processor *pr)
>                                    &pr->cdev->device.kobj,
>                                    "thermal_cooling");
>         if (result) {
> -               printk(KERN_ERR PREFIX "Create sysfs link\n");
> +               dev_err(&device->dev,
> +                       "Failed to create sysfs link 'thermal_cooling'\n");
>                 goto err_thermal_unregister;
>         }
>         result = sysfs_create_link(&pr->cdev->device.kobj,
>                                    &device->dev.kobj,
>                                    "device");
>         if (result) {
> -               printk(KERN_ERR PREFIX "Create sysfs link\n");
> +               dev_err(&pr->cdev->device,
> +                       "Failed to create sysfs link 'device'\n");
>                 goto err_remove_sysfs_thermal;
>         }
>
> @@ -560,8 +565,7 @@ static int __cpuinit acpi_processor_add(struct acpi_device *device)
>          */
>         if (per_cpu(processor_device_array, pr->id) != NULL &&
>             per_cpu(processor_device_array, pr->id) != device) {
> -               printk(KERN_WARNING "BIOS reported wrong ACPI id "
> -                       "for the processor\n");
> +               pr_warn("BIOS reported wrong ACPI id for the processor\n");

And this.

>                 result = -ENODEV;
>                 goto err_free_cpumask;
>         }
> @@ -715,7 +719,7 @@ static void acpi_processor_hotplug_notify(acpi_handle handle,
>
>                 result = acpi_processor_device_add(handle, &device);
>                 if (result) {
> -                       pr_err(PREFIX "Unable to add the device\n");
> +                       acpi_pr_err(handle, "Unable to add the device\n");
>                         break;
>                 }
>
> @@ -727,17 +731,19 @@ static void acpi_processor_hotplug_notify(acpi_handle handle,
>                                   "received ACPI_NOTIFY_EJECT_REQUEST\n"));
>
>                 if (acpi_bus_get_device(handle, &device)) {
> -                       pr_err(PREFIX "Device don't exist, dropping EJECT\n");
> +                       acpi_pr_err(handle,
> +                               "Device don't exist, dropping EJECT\n");
>                         break;
>                 }
>                 if (!acpi_driver_data(device)) {
> -                       pr_err(PREFIX "Driver data is NULL, dropping EJECT\n");
> +                       acpi_pr_err(handle,
> +                               "Driver data is NULL, dropping EJECT\n");

And this.

>                         break;
>                 }
>
>                 ej_event = kmalloc(sizeof(*ej_event), GFP_KERNEL);
>                 if (!ej_event) {
> -                       pr_err(PREFIX "No memory, dropping EJECT\n");
> +                       acpi_pr_err(handle, "No memory, dropping EJECT\n");

And this.

>                         break;
>                 }
>
> @@ -847,7 +853,7 @@ static acpi_status acpi_processor_hotadd_init(struct acpi_processor *pr)
>          * and do it when the CPU gets online the first time
>          * TBD: Cleanup above functions and try to do this more elegant.
>          */
> -       printk(KERN_INFO "CPU %d got hotplugged\n", pr->id);
> +       pr_info("CPU %d got hotplugged\n", pr->id);

And this.  The caller (acpi_processor_get_info()) has an acpi_device
*, so we should be able to use it here.

>         pr->flags.need_hotplug_init = 1;
>
>         return AE_OK;
> --
> 1.7.7.6
>

Re: [PATCH v3 3/4] ACPI: Update Memory hotplug messages

[Bjorn Helgaas]

On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> Updated Memory hotplug log messages with acpi_pr_<level>()
> and pr_<level>().
>
> Signed-off-by: Toshi Kani <toshi.kani@hp.com>
> ---
>  drivers/acpi/acpi_memhotplug.c |   24 ++++++++++++------------
>  1 files changed, 12 insertions(+), 12 deletions(-)
>
> diff --git a/drivers/acpi/acpi_memhotplug.c b/drivers/acpi/acpi_memhotplug.c
> index 06c55cd..dcc8f4d 100644
> --- a/drivers/acpi/acpi_memhotplug.c
> +++ b/drivers/acpi/acpi_memhotplug.c
> @@ -170,7 +170,7 @@ acpi_memory_get_device(acpi_handle handle,
>         /* Get the parent device */
>         result = acpi_bus_get_device(phandle, &pdevice);
>         if (result) {
> -               printk(KERN_WARNING PREFIX "Cannot get acpi bus device");
> +               acpi_pr_warn(phandle, "Cannot get acpi bus device\n");
>                 return -EINVAL;
>         }
>
> @@ -180,14 +180,14 @@ acpi_memory_get_device(acpi_handle handle,
>          */
>         result = acpi_bus_add(&device, pdevice, handle, ACPI_BUS_TYPE_DEVICE);
>         if (result) {
> -               printk(KERN_WARNING PREFIX "Cannot add acpi bus");
> +               acpi_pr_warn(handle, "Cannot add acpi bus\n");
>                 return -EINVAL;
>         }
>
>        end:
>         *mem_device = acpi_driver_data(device);
>         if (!(*mem_device)) {
> -               printk(KERN_ERR "\n driver data not found");
> +               acpi_pr_err(handle, "driver data not found\n");

acpi_driver_data() requires a valid acpi_device *, so dev_err() should
work here.

>                 return -ENODEV;
>         }
>
> @@ -224,7 +224,7 @@ static int acpi_memory_enable_device(struct acpi_memory_device *mem_device)
>         /* Get the range from the _CRS */
>         result = acpi_memory_get_device_resources(mem_device);
>         if (result) {
> -               printk(KERN_ERR PREFIX "get_device_resources failed\n");
> +               pr_err(PREFIX "get_device_resources failed\n");

And here.

>                 mem_device->state = MEMORY_INVALID_STATE;
>                 return result;
>         }
> @@ -257,7 +257,7 @@ static int acpi_memory_enable_device(struct acpi_memory_device *mem_device)
>                 num_enabled++;
>         }
>         if (!num_enabled) {
> -               printk(KERN_ERR PREFIX "add_memory failed\n");
> +               acpi_pr_err(mem_device->device->handle, "add_memory failed\n");

And here.

>                 mem_device->state = MEMORY_INVALID_STATE;
>                 return -EINVAL;
>         }
> @@ -353,7 +353,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
>                         ACPI_DEBUG_PRINT((ACPI_DB_INFO,
>                                           "\nReceived DEVICE CHECK notification for device\n"));
>                 if (acpi_memory_get_device(handle, &mem_device)) {
> -                       printk(KERN_ERR PREFIX "Cannot find driver data\n");
> +                       acpi_pr_err(handle, "Cannot find driver data\n");
>                         break;
>                 }
>
> @@ -361,7 +361,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
>                         break;
>
>                 if (acpi_memory_enable_device(mem_device)) {
> -                       pr_err(PREFIX "Cannot enable memory device\n");
> +                       acpi_pr_err(handle, "Cannot enable memory device\n");

And here.

>                         break;
>                 }
>
> @@ -373,12 +373,12 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
>                                   "\nReceived EJECT REQUEST notification for device\n"));
>
>                 if (acpi_bus_get_device(handle, &device)) {
> -                       printk(KERN_ERR PREFIX "Device doesn't exist\n");
> +                       acpi_pr_err(handle, "Device doesn't exist\n");
>                         break;
>                 }
>                 mem_device = acpi_driver_data(device);
>                 if (!mem_device) {
> -                       printk(KERN_ERR PREFIX "Driver Data is NULL\n");
> +                       acpi_pr_err(handle, "Driver Data is NULL\n");

And here.

>                         break;
>                 }
>
> @@ -389,7 +389,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
>                  *      with generic sysfs driver
>                  */
>                 if (acpi_memory_disable_device(mem_device)) {
> -                       pr_err(PREFIX "Disable memory device\n");
> +                       acpi_pr_err(handle, "Disable memory device\n");

And here.  (What is this message supposed to mean, anyway?)

>                         /*
>                          * If _EJ0 was called but failed, _OST is not
>                          * necessary.
> @@ -449,7 +449,7 @@ static int acpi_memory_device_add(struct acpi_device *device)
>         /* Set the device state */
>         mem_device->state = MEMORY_POWER_ON_STATE;
>
> -       printk(KERN_DEBUG "%s \n", acpi_device_name(device));
> +       pr_debug("%s\n", acpi_device_name(device));

And here.  This message looks dubious anyway.

>
>         /*
>          * Early boot code has recognized memory area by EFI/E820.
> @@ -464,7 +464,7 @@ static int acpi_memory_device_add(struct acpi_device *device)
>                 /* call add_memory func */
>                 result = acpi_memory_enable_device(mem_device);
>                 if (result)
> -                       printk(KERN_ERR PREFIX
> +                       acpi_pr_err(device->handle,
>                                 "Error in acpi_memory_enable_device\n");

And here.

>         }
>         return result;
> --
> 1.7.7.6
>

Re: [PATCH v3 4/4] ACPI: Update Container hotplug messages

[Bjorn Helgaas]

On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> Updated Container hotplug log messages with acpi_pr_<level>()
> and pr_<level>().
>
> Signed-off-by: Toshi Kani <toshi.kani@hp.com>
> ---
>  drivers/acpi/container.c |    6 +++---
>  1 files changed, 3 insertions(+), 3 deletions(-)
>
> diff --git a/drivers/acpi/container.c b/drivers/acpi/container.c
> index 01a986d..643e962 100644
> --- a/drivers/acpi/container.c
> +++ b/drivers/acpi/container.c
> @@ -99,7 +99,7 @@ static int acpi_container_add(struct acpi_device *device)
>
>
>         if (!device) {
> -               printk(KERN_ERR PREFIX "device is NULL\n");
> +               pr_err(PREFIX "device is NULL\n");
>                 return -EINVAL;
>         }

This whole "if (!device)" check and the printk should be deleted.  If
the ACPI core calls .add() with a null acpi_device pointer, it's a
core bug, and it's better to take the oops and get the backtrace.

>
> @@ -164,7 +164,7 @@ static void container_notify_cb(acpi_handle handle, u32 type, void *context)
>         case ACPI_NOTIFY_BUS_CHECK:
>                 /* Fall through */
>         case ACPI_NOTIFY_DEVICE_CHECK:
> -               printk(KERN_WARNING "Container driver received %s event\n",
> +               pr_warn("Container driver received %s event\n",
>                        (type == ACPI_NOTIFY_BUS_CHECK) ?
>                        "ACPI_NOTIFY_BUS_CHECK" : "ACPI_NOTIFY_DEVICE_CHECK");

This message looks dubious.  Receiving this event should be a normal
occurrence, so the message might be useful for debugging, but doesn't
seem like a KERN_WARNING event for the user.

>
> @@ -185,7 +185,7 @@ static void container_notify_cb(acpi_handle handle, u32 type, void *context)
>
>                 result = container_device_add(&device, handle);
>                 if (result) {
> -                       pr_warn("Failed to add container\n");
> +                       acpi_pr_warn(handle, "Failed to add container\n");
>                         break;
>                 }
>
> --
> 1.7.7.6
>

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Toshi Kani]

On Thu, 2012-07-26 at 13:22 -0600, Bjorn Helgaas wrote:
> On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> > This patch introduces acpi_pr_<level>(), where <level> is a kernel
> > message level such as err/warn/info, to support improved logging
> > messages for ACPI, esp. in hotplug operations.  acpi_pr_<level>()
> > appends "ACPI" prefix and ACPI object path to the messages.  This
> > improves diagnostics in hotplug operations since it identifies an
> > object that caused an issue in a log file.
> >
> > acpi_pr_<level>() takes acpi_handle as an argument, which is passed
> > to ACPI hotplug notify handlers from the ACPICA.  Therefore, it is
> > always available unlike other kernel objects, such as device.
> >
> > For example, the statement below
> >   acpi_pr_err(handle, "Device don't exist, dropping EJECT\n");
> > logs an error message like this at KERN_ERR.
> >   ACPI: \_SB_.SCK4.CPU4: Device don't exist, dropping EJECT
> >
> > ACPI drivers can use acpi_pr_<level>() when they need to identify
> > a target ACPI object in their messages, such as error messages.
> 
> It's definitely an improvement to have *something* that identifies a
> device in these messages.  But the ACPI namespace path is not really
> intended to be user-consumable, so I don't think we should expose it
> indiscriminately.  I think we should be using the ACPI device name
> ("PNP0C02:00") whenever possible.  Given the device name, we can get
> the path from the sysfs "path" file.

Hi Bjorn,

Thanks for reviewing!  Yes, ACPI device path is not good for regular
users to analyze from the info.  I also agree with you that device name
is a better choice when users always diagnose issues by themselves right
after they performed an operation.  However, there are also cases that
users ask someone to diagnose an issue remotely from the log files, and
hotplug operations are performed automatically.  In such cases, using
ACPI device name alone is problematic for hotplug operations since a
device name comes with an instance number that continues to change with
hot-add/remove operations.  Here is one example scenario.  Let's say,
user has automatic load-balancer or power-saving that can trigger
hundreds of CPU hotplug operations per a day.  This user then found that
there were multiple hotplug errors logged in the past few days, and
asked an IT guy to look at the error messages.  When this user found the
issue, all device names are gone from sysfs after repeated hotplug
operations.  This IT guy would have no idea if those errors were
happening on a particular device or not from the error messages since
their instance numbers continue to change.

> > The usage model is similar to dev_<level>().  acpi_pr_<level>() can
> > be used when device is not created/valid, which may be the case for
> > ACPI hotplug handlers.  ACPI drivers can continue to use dev_<level>()
> > when device is valid.
> 
> I'd argue that ACPI driver code should never be called unless the
> device is valid, so drivers should *always* be able to use
> dev_<level>.  Obviously, ACPI hotplug is currently screwed up (it's
> mostly handled in drivers rather than in the ACPI core), so in some of
> those hotplug paths in the drivers, we may not have a device yet.  But
> those cases should be minimal.

I think it makes sense for ACPI hotplug notify handlers to use
acpi_pr_<level>() for their error messages since ACPI device names are
static on the platform.  This info greatly helps in the scenario I
described above.  In the outside of the hotplug notify handlers, I agree
with you that dev_<level>() should be used.

> Another possible approach to this is to add a %p extension rather than
> adding acpi_printk().  Then you could do, e.g., 'printk("%pA ...\n",
> handle)', and printk could interpolate the namespace path.  But I
> really think there should be very few places where we need the path,
> so I'm not sure it's worth it.

Address of handle is not very helpful either when someone needs to
analyze from log files.

Thanks,
-Toshi


> > ACPI drivers also continue to use pr_<level>() when ACPI device
> > path does not have to be appended to the messages, such as boot-up
> > messages.
> >
> > Note: ACPI_[WARNING|INFO|ERROR]() are intended for the ACPICA and
> > are not associated with the kernel message level.
> >
> > Signed-off-by: Toshi Kani <toshi.kani@hp.com>
> > Tested-by: Vijay Mohan Pandarathil <vijaymohan.pandarathil@hp.com>
> > ---
> >  drivers/acpi/utils.c    |   34 ++++++++++++++++++++++++++++++++++
> >  include/acpi/acpi_bus.h |   31 +++++++++++++++++++++++++++++++
> >  2 files changed, 65 insertions(+), 0 deletions(-)
> >
> > diff --git a/drivers/acpi/utils.c b/drivers/acpi/utils.c
> > index 3e87c9c..ec0c6f9 100644
> > --- a/drivers/acpi/utils.c
> > +++ b/drivers/acpi/utils.c
> > @@ -454,3 +454,37 @@ acpi_evaluate_hotplug_ost(acpi_handle handle, u32 source_event,
> >  #endif
> >  }
> >  EXPORT_SYMBOL(acpi_evaluate_hotplug_ost);
> > +
> > +/**
> > + * acpi_printk: Print messages with ACPI prefix and object path
> > + *
> > + * This function is intended to be called through acpi_pr_<level> macros.
> > + */
> > +void
> > +acpi_printk(const char *level, acpi_handle handle, const char *fmt, ...)
> > +{
> > +       struct va_format vaf;
> > +       va_list args;
> > +       struct acpi_buffer buffer = {
> > +               .length = ACPI_ALLOCATE_BUFFER,
> > +               .pointer = NULL
> > +       };
> > +       const char *path;
> > +       acpi_status ret;
> > +
> > +       va_start(args, fmt);
> > +       vaf.fmt = fmt;
> > +       vaf.va = &args;
> > +
> > +       ret = acpi_get_name(handle, ACPI_FULL_PATHNAME, &buffer);
> > +       if (ret == AE_OK)
> > +               path = buffer.pointer;
> > +       else
> > +               path = "<n/a>";
> > +
> > +       printk("%sACPI: %s: %pV", level, path, &vaf);
> > +
> > +       va_end(args);
> > +       kfree(buffer.pointer);
> > +}
> > +EXPORT_SYMBOL(acpi_printk);
> > diff --git a/include/acpi/acpi_bus.h b/include/acpi/acpi_bus.h
> > index bde976e..1c855b8 100644
> > --- a/include/acpi/acpi_bus.h
> > +++ b/include/acpi/acpi_bus.h
> > @@ -85,6 +85,37 @@ struct acpi_pld {
> >
> >  acpi_status
> >  acpi_get_physical_device_location(acpi_handle handle, struct acpi_pld *pld);
> > +
> > +void acpi_printk(const char *level, acpi_handle handle, const char *fmt, ...);
> > +
> > +#define acpi_pr_emerg(handle, fmt, ...)                                \
> > +       acpi_printk(KERN_EMERG, handle, fmt, ##__VA_ARGS__)
> > +#define acpi_pr_alert(handle, fmt, ...)                                \
> > +       acpi_printk(KERN_ALERT, handle, fmt, ##__VA_ARGS__)
> > +#define acpi_pr_crit(handle, fmt, ...)                         \
> > +       acpi_printk(KERN_CRIT, handle, fmt, ##__VA_ARGS__)
> > +#define acpi_pr_err(handle, fmt, ...)                          \
> > +       acpi_printk(KERN_ERR, handle, fmt, ##__VA_ARGS__)
> > +#define acpi_pr_warn(handle, fmt, ...)                         \
> > +       acpi_printk(KERN_WARNING, handle, fmt, ##__VA_ARGS__)
> > +#define acpi_pr_notice(handle, fmt, ...)                       \
> > +       acpi_printk(KERN_NOTICE, handle, fmt, ##__VA_ARGS__)
> > +#define acpi_pr_info(handle, fmt, ...)                         \
> > +       acpi_printk(KERN_INFO, handle, fmt, ##__VA_ARGS__)
> > +
> > +/* REVISIT: Need to support CONFIG_DYNAMIC_DEBUG */
> > +#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)
> > +#define acpi_pr_debug(handle, fmt, ...)                                        \
> > +       acpi_printk(KERN_DEBUG, handle, fmt, ##__VA_ARGS__)
> > +#else
> > +#define acpi_pr_debug(handle, fmt, ...)                                        \
> > +({                                                                     \
> > +       if (0)                                                          \
> > +               acpi_printk(KERN_DEBUG, handle, fmt, ##__VA_ARGS__);    \
> > +       0;                                                              \
> > +})
> > +#endif
> > +
> >  #ifdef CONFIG_ACPI
> >
> >  #include <linux/proc_fs.h>
> > --
> > 1.7.7.6
> >

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Bjorn Helgaas]

On Thu, Jul 26, 2012 at 02:58:50PM -0600, Toshi Kani wrote:
> On Thu, 2012-07-26 at 13:22 -0600, Bjorn Helgaas wrote:
> > On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> > > This patch introduces acpi_pr_<level>(), where <level> is a kernel
> > > message level such as err/warn/info, to support improved logging
> > > messages for ACPI, esp. in hotplug operations.  acpi_pr_<level>()
> > > appends "ACPI" prefix and ACPI object path to the messages.  This
> > > improves diagnostics in hotplug operations since it identifies an
> > > object that caused an issue in a log file.
> > >
> > > acpi_pr_<level>() takes acpi_handle as an argument, which is passed
> > > to ACPI hotplug notify handlers from the ACPICA.  Therefore, it is
> > > always available unlike other kernel objects, such as device.
> > >
> > > For example, the statement below
> > >   acpi_pr_err(handle, "Device don't exist, dropping EJECT\n");
> > > logs an error message like this at KERN_ERR.
> > >   ACPI: \_SB_.SCK4.CPU4: Device don't exist, dropping EJECT
> > >
> > > ACPI drivers can use acpi_pr_<level>() when they need to identify
> > > a target ACPI object in their messages, such as error messages.
> > 
> > It's definitely an improvement to have *something* that identifies a
> > device in these messages.  But the ACPI namespace path is not really
> > intended to be user-consumable, so I don't think we should expose it
> > indiscriminately.  I think we should be using the ACPI device name
> > ("PNP0C02:00") whenever possible.  Given the device name, we can get
> > the path from the sysfs "path" file.
> 
> Hi Bjorn,
> 
> Thanks for reviewing!  Yes, ACPI device path is not good for regular
> users to analyze from the info.  I also agree with you that device name
> is a better choice when users always diagnose issues by themselves right
> after they performed an operation.  However, there are also cases that
> users ask someone to diagnose an issue remotely from the log files, and
> hotplug operations are performed automatically.  In such cases, using
> ACPI device name alone is problematic for hotplug operations since a
> device name comes with an instance number that continues to change with
> hot-add/remove operations.  Here is one example scenario.  Let's say,
> user has automatic load-balancer or power-saving that can trigger
> hundreds of CPU hotplug operations per a day.  This user then found that
> there were multiple hotplug errors logged in the past few days, and
> asked an IT guy to look at the error messages.  When this user found the
> issue, all device names are gone from sysfs after repeated hotplug
> operations.  This IT guy would have no idea if those errors were
> happening on a particular device or not from the error messages since
> their instance numbers continue to change.

I agree that it's useful to be able to debug from the dmesg log
without having to ask a user to collect stuff from /sys.  But rather
than including the namespace path in every message, I think it'd be
better to do one dev_info() in the hotplug notify event handler and
include the path there.  Subsequent messages can just use dev_info()
without the namespace info.

> > Another possible approach to this is to add a %p extension rather than
> > adding acpi_printk().  Then you could do, e.g., 'printk("%pA ...\n",
> > handle)', and printk could interpolate the namespace path.  But I
> > really think there should be very few places where we need the path,
> > so I'm not sure it's worth it.
> 
> Address of handle is not very helpful either when someone needs to
> analyze from log files.

Sorry, I should have made this clearer.  The %pA would expand to the ACPI
namespace path, so a "dev_info(dev, "new device for %pA\n", dev->handle)"
would produce output like this:

    PNP0C01:00: new device for \_SB_.PCI0.ISA_.MBIO

I fiddled with this a while ago; it would look something like this:

diff --git a/lib/vsprintf.c b/lib/vsprintf.c
index c3f36d41..201dcdb 100644
--- a/lib/vsprintf.c
+++ b/lib/vsprintf.c
@@ -551,6 +551,29 @@ char *symbol_string(char *buf, char *end, void *ptr,
 #endif
 }
 
+#ifdef CONFIG_ACPI
+#include <acpi/acpi.h>
+
+static noinline_for_stack
+char *acpi_name_string(char *buf, char *end, acpi_handle handle,
+		       struct printf_spec spec, const char *fmt)
+{
+	acpi_status status;
+	struct acpi_buffer buffer = { ACPI_ALLOCATE_BUFFER, NULL };
+	u32 type = ACPI_SINGLE_NAME;
+	char *p = buf;
+
+	if (fmt[0] == 'A')
+		type = ACPI_FULL_PATHNAME;
+
+	status = acpi_get_name(handle, type, &buffer);
+	if (ACPI_SUCCESS(status))
+		p = string(buf, end, buffer.pointer, spec);
+	kfree(buffer.pointer);
+	return p;
+}
+#endif
+
 static noinline_for_stack
 char *resource_string(char *buf, char *end, struct resource *res,
 		      struct printf_spec spec, const char *fmt)
@@ -921,6 +944,8 @@ int kptr_restrict __read_mostly;
  *
  * Right now we handle:
  *
+ * - 'A' For full ACPI namespace names
+ * - 'a' For single segment ACPI namespace names
  * - 'F' For symbolic function descriptor pointers with offset
  * - 'f' For simple symbolic function names without offset
  * - 'S' For symbolic direct pointers with offset
@@ -982,6 +1007,9 @@ char *pointer(const char *fmt, char *buf, char *end, void *ptr,
 	}
 
 	switch (*fmt) {
+	case 'A':
+	case 'a':
+		return acpi_name_string(buf, end, ptr, spec, fmt);
 	case 'F':
 	case 'f':
 		ptr = dereference_function_descriptor(ptr);

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Joe Perches]

On Thu, 2012-07-26 at 15:37 -0600, Bjorn Helgaas wrote:
>     PNP0C01:00: new device for \_SB_.PCI0.ISA_.MBIO
> 
> I fiddled with this a while ago; it would look something like this:
[]
> +static noinline_for_stack
> +char *acpi_name_string(char *buf, char *end, acpi_handle handle,
> +		       struct printf_spec spec, const char *fmt)
> +{
> +	acpi_status status;
> +	struct acpi_buffer buffer = { ACPI_ALLOCATE_BUFFER, NULL };
> +	u32 type = ACPI_SINGLE_NAME;
> +	char *p = buf;
> +
> +	if (fmt[0] == 'A')
> +		type = ACPI_FULL_PATHNAME;

maybe if (fmt[1] == 'f')

> @@ -982,6 +1007,9 @@ char *pointer(const char *fmt, char *buf, char *end, void *ptr,
>  	}
>  
>  	switch (*fmt) {
> +	case 'A':
> +	case 'a':
> +		return acpi_name_string(buf, end, ptr, spec, fmt);

There are only so many letters, it might be better to
just use 'a' and another 'f' after that if necessary
for "full".

And of course that should be #ifdef'd too

cheers, Joe

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Toshi Kani]

On Thu, 2012-07-26 at 15:37 -0600, Bjorn Helgaas wrote:
> On Thu, Jul 26, 2012 at 02:58:50PM -0600, Toshi Kani wrote:
> > On Thu, 2012-07-26 at 13:22 -0600, Bjorn Helgaas wrote:
> > > On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> > > > This patch introduces acpi_pr_<level>(), where <level> is a kernel
> > > > message level such as err/warn/info, to support improved logging
> > > > messages for ACPI, esp. in hotplug operations.  acpi_pr_<level>()
> > > > appends "ACPI" prefix and ACPI object path to the messages.  This
> > > > improves diagnostics in hotplug operations since it identifies an
> > > > object that caused an issue in a log file.
> > > >
> > > > acpi_pr_<level>() takes acpi_handle as an argument, which is passed
> > > > to ACPI hotplug notify handlers from the ACPICA.  Therefore, it is
> > > > always available unlike other kernel objects, such as device.
> > > >
> > > > For example, the statement below
> > > >   acpi_pr_err(handle, "Device don't exist, dropping EJECT\n");
> > > > logs an error message like this at KERN_ERR.
> > > >   ACPI: \_SB_.SCK4.CPU4: Device don't exist, dropping EJECT
> > > >
> > > > ACPI drivers can use acpi_pr_<level>() when they need to identify
> > > > a target ACPI object in their messages, such as error messages.
> > > 
> > > It's definitely an improvement to have *something* that identifies a
> > > device in these messages.  But the ACPI namespace path is not really
> > > intended to be user-consumable, so I don't think we should expose it
> > > indiscriminately.  I think we should be using the ACPI device name
> > > ("PNP0C02:00") whenever possible.  Given the device name, we can get
> > > the path from the sysfs "path" file.
> > 
> > Hi Bjorn,
> > 
> > Thanks for reviewing!  Yes, ACPI device path is not good for regular
> > users to analyze from the info.  I also agree with you that device name
> > is a better choice when users always diagnose issues by themselves right
> > after they performed an operation.  However, there are also cases that
> > users ask someone to diagnose an issue remotely from the log files, and
> > hotplug operations are performed automatically.  In such cases, using
> > ACPI device name alone is problematic for hotplug operations since a
> > device name comes with an instance number that continues to change with
> > hot-add/remove operations.  Here is one example scenario.  Let's say,
> > user has automatic load-balancer or power-saving that can trigger
> > hundreds of CPU hotplug operations per a day.  This user then found that
> > there were multiple hotplug errors logged in the past few days, and
> > asked an IT guy to look at the error messages.  When this user found the
> > issue, all device names are gone from sysfs after repeated hotplug
> > operations.  This IT guy would have no idea if those errors were
> > happening on a particular device or not from the error messages since
> > their instance numbers continue to change.
> 
> I agree that it's useful to be able to debug from the dmesg log
> without having to ask a user to collect stuff from /sys.  But rather
> than including the namespace path in every message, I think it'd be
> better to do one dev_info() in the hotplug notify event handler and
> include the path there.  Subsequent messages can just use dev_info()
> without the namespace info.

Hi Bjorn,

I agree.  For now, I will keep the use of acpi_pr_<level>() within the
hotplug notify handler functions.  I will change any subsequent
functions to use dev_<level>().  This way, we have only one use of
acpi_pr_<level>() in an operation.  I will also clarify this in the
change log.

> > > Another possible approach to this is to add a %p extension rather than
> > > adding acpi_printk().  Then you could do, e.g., 'printk("%pA ...\n",
> > > handle)', and printk could interpolate the namespace path.  But I
> > > really think there should be very few places where we need the path,
> > > so I'm not sure it's worth it.
> > 
> > Address of handle is not very helpful either when someone needs to
> > analyze from log files.
> 
> Sorry, I should have made this clearer.  The %pA would expand to the ACPI
> namespace path, so a "dev_info(dev, "new device for %pA\n", dev->handle)"
> would produce output like this:
> 
>     PNP0C01:00: new device for \_SB_.PCI0.ISA_.MBIO
> 
> I fiddled with this a while ago; it would look something like this:

I see.  That sounds good idea.  I agree that we can use it when device
is valid.  Since it's late to make such changes, I will consider making
such changes for 3.7. 

Thanks,
-Toshi


> diff --git a/lib/vsprintf.c b/lib/vsprintf.c
> index c3f36d41..201dcdb 100644
> --- a/lib/vsprintf.c
> +++ b/lib/vsprintf.c
> @@ -551,6 +551,29 @@ char *symbol_string(char *buf, char *end, void *ptr,
>  #endif
>  }
>  
> +#ifdef CONFIG_ACPI
> +#include <acpi/acpi.h>
> +
> +static noinline_for_stack
> +char *acpi_name_string(char *buf, char *end, acpi_handle handle,
> +		       struct printf_spec spec, const char *fmt)
> +{
> +	acpi_status status;
> +	struct acpi_buffer buffer = { ACPI_ALLOCATE_BUFFER, NULL };
> +	u32 type = ACPI_SINGLE_NAME;
> +	char *p = buf;
> +
> +	if (fmt[0] == 'A')
> +		type = ACPI_FULL_PATHNAME;
> +
> +	status = acpi_get_name(handle, type, &buffer);
> +	if (ACPI_SUCCESS(status))
> +		p = string(buf, end, buffer.pointer, spec);
> +	kfree(buffer.pointer);
> +	return p;
> +}
> +#endif
> +
>  static noinline_for_stack
>  char *resource_string(char *buf, char *end, struct resource *res,
>  		      struct printf_spec spec, const char *fmt)
> @@ -921,6 +944,8 @@ int kptr_restrict __read_mostly;
>   *
>   * Right now we handle:
>   *
> + * - 'A' For full ACPI namespace names
> + * - 'a' For single segment ACPI namespace names
>   * - 'F' For symbolic function descriptor pointers with offset
>   * - 'f' For simple symbolic function names without offset
>   * - 'S' For symbolic direct pointers with offset
> @@ -982,6 +1007,9 @@ char *pointer(const char *fmt, char *buf, char *end, void *ptr,
>  	}
>  
>  	switch (*fmt) {
> +	case 'A':
> +	case 'a':
> +		return acpi_name_string(buf, end, ptr, spec, fmt);
>  	case 'F':
>  	case 'f':
>  		ptr = dereference_function_descriptor(ptr);

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Bjorn Helgaas]

On Thu, Jul 26, 2012 at 3:43 PM, Joe Perches <joe@perches.com> wrote:
> On Thu, 2012-07-26 at 15:37 -0600, Bjorn Helgaas wrote:
>>     PNP0C01:00: new device for \_SB_.PCI0.ISA_.MBIO
>>
>> I fiddled with this a while ago; it would look something like this:
> []
>> +static noinline_for_stack
>> +char *acpi_name_string(char *buf, char *end, acpi_handle handle,
>> +                    struct printf_spec spec, const char *fmt)
>> +{
>> +     acpi_status status;
>> +     struct acpi_buffer buffer = { ACPI_ALLOCATE_BUFFER, NULL };
>> +     u32 type = ACPI_SINGLE_NAME;
>> +     char *p = buf;
>> +
>> +     if (fmt[0] == 'A')
>> +             type = ACPI_FULL_PATHNAME;
>
> maybe if (fmt[1] == 'f')
>
>> @@ -982,6 +1007,9 @@ char *pointer(const char *fmt, char *buf, char *end, void *ptr,
>>       }
>>
>>       switch (*fmt) {
>> +     case 'A':
>> +     case 'a':
>> +             return acpi_name_string(buf, end, ptr, spec, fmt);
>
> There are only so many letters, it might be better to
> just use 'a' and another 'f' after that if necessary
> for "full".
>
> And of course that should be #ifdef'd too

Yes.  I'm hesitant about this approach in general, because I don't
think printing the ACPI path is something we should be doing often.
It's not like a struct resource or a MAC address, where there are
dozens or hundreds of users.  I really think we should only print ACPI
paths in one or two places, so adding a %p extension would waste a
letter and encourage the wrong behavior.

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Joe Perches]

On Thu, 2012-07-26 at 15:50 -0600, Bjorn Helgaas wrote:
> On Thu, Jul 26, 2012 at 3:43 PM, Joe Perches <joe@perches.com> wrote:
> > On Thu, 2012-07-26 at 15:37 -0600, Bjorn Helgaas wrote:
> >>     PNP0C01:00: new device for \_SB_.PCI0.ISA_.MBIO
> >>
> >> I fiddled with this a while ago; it would look something like this:
> > []
> >> +static noinline_for_stack
> >> +char *acpi_name_string(char *buf, char *end, acpi_handle handle,
> >> +                    struct printf_spec spec, const char *fmt)
[]
> Yes.  I'm hesitant about this approach in general, because I don't
> think printing the ACPI path is something we should be doing often.
> It's not like a struct resource or a MAC address, where there are
> dozens or hundreds of users.  I really think we should only print ACPI
> paths in one or two places, so adding a %p extension would waste a
> letter and encourage the wrong behavior.

I don't much care for adding ACPI specific calls to vsprintf
as acpi is supposed to be OS generic anyway.

I don't think there's anything wrong with Toshi's approach.
Anyone that looks for speed in a logging message is looking
for an oddly fitting thing.  Tracing sure, but logging?

I also don't see anything wrong with renaming it to just
acpi_<level>, but that's a different discussion.

cheers, Joe

Re: [PATCH v3 2/4] ACPI: Update CPU hotplug messages

[Toshi Kani]

On Thu, 2012-07-26 at 13:23 -0600, Bjorn Helgaas wrote:
> On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> > Updated CPU hotplug log messages with acpi_pr_<level>(),
> > dev_<level>() and pr_<level>().  Some messages are also
> > changed for clarity.
> >
> > Signed-off-by: Toshi Kani <toshi.kani@hp.com>
> > Tested-by: Vijay Mohan Pandarathil <vijaymohan.pandarathil@hp.com>
> > ---
> >  drivers/acpi/processor_driver.c |   36 +++++++++++++++++++++---------------
> >  1 files changed, 21 insertions(+), 15 deletions(-)
> >
> > diff --git a/drivers/acpi/processor_driver.c b/drivers/acpi/processor_driver.c
> > index a6bdeaa..225f252 100644
> > --- a/drivers/acpi/processor_driver.c
> > +++ b/drivers/acpi/processor_driver.c
> > @@ -282,7 +282,9 @@ static int acpi_processor_get_info(struct acpi_device *device)
> >                 /* Declared with "Processor" statement; match ProcessorID */
> >                 status = acpi_evaluate_object(pr->handle, NULL, NULL, &buffer);
> >                 if (ACPI_FAILURE(status)) {
> > -                       printk(KERN_ERR PREFIX "Evaluating processor object\n");
> > +                       acpi_pr_err(pr->handle,
> > +                               "Failed to evaluate processor object (0x%x)\n",
> > +                               status);
> 
> This looks like it could be a dev_err().

Agreed. Changed to use dev_err().

> >                         return -ENODEV;
> >                 }
> >
> > @@ -301,8 +303,9 @@ static int acpi_processor_get_info(struct acpi_device *device)
> >                 status = acpi_evaluate_integer(pr->handle, METHOD_NAME__UID,
> >                                                 NULL, &value);
> >                 if (ACPI_FAILURE(status)) {
> > -                       printk(KERN_ERR PREFIX
> > -                           "Evaluating processor _UID [%#x]\n", status);
> > +                       acpi_pr_err(pr->handle,
> > +                               "Failed to evaluate processor _UID (0x%x)\n",
> > +                               status);
> 
> And this.

Changed to use dev_err().

> >                         return -ENODEV;
> >                 }
> >                 device_declaration = 1;
> > @@ -345,7 +348,7 @@ static int acpi_processor_get_info(struct acpi_device *device)
> >         if (!object.processor.pblk_address)
> >                 ACPI_DEBUG_PRINT((ACPI_DB_INFO, "No PBLK (NULL address)\n"));
> >         else if (object.processor.pblk_length != 6)
> > -               printk(KERN_ERR PREFIX "Invalid PBLK length [%d]\n",
> > +               acpi_pr_err(pr->handle, "Invalid PBLK length [%d]\n",
> 
> And this.

Changed to use dev_err().

> 
> >                             object.processor.pblk_length);
> >         else {
> >                 pr->throttling.address = object.processor.pblk_address;
> > @@ -429,8 +432,8 @@ static int acpi_cpu_soft_notify(struct notifier_block *nfb,
> >                  * Initialize missing things
> >                  */
> >                 if (pr->flags.need_hotplug_init) {
> > -                       printk(KERN_INFO "Will online and init hotplugged "
> > -                              "CPU: %d\n", pr->id);
> > +                       pr_info("Will online and init hotplugged CPU: %d\n",
> > +                               pr->id);
> >                         WARN(acpi_processor_start(pr), "Failed to start CPU:"
> >                                 " %d\n", pr->id);
> >                         pr->flags.need_hotplug_init = 0;
> > @@ -491,14 +494,16 @@ static __ref int acpi_processor_start(struct acpi_processor *pr)
> >                                    &pr->cdev->device.kobj,
> >                                    "thermal_cooling");
> >         if (result) {
> > -               printk(KERN_ERR PREFIX "Create sysfs link\n");
> > +               dev_err(&device->dev,
> > +                       "Failed to create sysfs link 'thermal_cooling'\n");
> >                 goto err_thermal_unregister;
> >         }
> >         result = sysfs_create_link(&pr->cdev->device.kobj,
> >                                    &device->dev.kobj,
> >                                    "device");
> >         if (result) {
> > -               printk(KERN_ERR PREFIX "Create sysfs link\n");
> > +               dev_err(&pr->cdev->device,
> > +                       "Failed to create sysfs link 'device'\n");
> >                 goto err_remove_sysfs_thermal;
> >         }
> >
> > @@ -560,8 +565,7 @@ static int __cpuinit acpi_processor_add(struct acpi_device *device)
> >          */
> >         if (per_cpu(processor_device_array, pr->id) != NULL &&
> >             per_cpu(processor_device_array, pr->id) != device) {
> > -               printk(KERN_WARNING "BIOS reported wrong ACPI id "
> > -                       "for the processor\n");
> > +               pr_warn("BIOS reported wrong ACPI id for the processor\n");
> 
> And this.

Changed to use dev_warn().

> >                 result = -ENODEV;
> >                 goto err_free_cpumask;
> >         }
> > @@ -715,7 +719,7 @@ static void acpi_processor_hotplug_notify(acpi_handle handle,
> >
> >                 result = acpi_processor_device_add(handle, &device);
> >                 if (result) {
> > -                       pr_err(PREFIX "Unable to add the device\n");
> > +                       acpi_pr_err(handle, "Unable to add the device\n");
> >                         break;
> >                 }
> >
> > @@ -727,17 +731,19 @@ static void acpi_processor_hotplug_notify(acpi_handle handle,
> >                                   "received ACPI_NOTIFY_EJECT_REQUEST\n"));
> >
> >                 if (acpi_bus_get_device(handle, &device)) {
> > -                       pr_err(PREFIX "Device don't exist, dropping EJECT\n");
> > +                       acpi_pr_err(handle,
> > +                               "Device don't exist, dropping EJECT\n");
> >                         break;
> >                 }
> >                 if (!acpi_driver_data(device)) {
> > -                       pr_err(PREFIX "Driver data is NULL, dropping EJECT\n");
> > +                       acpi_pr_err(handle,
> > +                               "Driver data is NULL, dropping EJECT\n");
> 
> And this.

No change since it is called directly from the handler.

> >                         break;
> >                 }
> >
> >                 ej_event = kmalloc(sizeof(*ej_event), GFP_KERNEL);
> >                 if (!ej_event) {
> > -                       pr_err(PREFIX "No memory, dropping EJECT\n");
> > +                       acpi_pr_err(handle, "No memory, dropping EJECT\n");
> 
> And this.

No change since it is called directly from the handler.

> >                         break;
> >                 }
> >
> > @@ -847,7 +853,7 @@ static acpi_status acpi_processor_hotadd_init(struct acpi_processor *pr)
> >          * and do it when the CPU gets online the first time
> >          * TBD: Cleanup above functions and try to do this more elegant.
> >          */
> > -       printk(KERN_INFO "CPU %d got hotplugged\n", pr->id);
> > +       pr_info("CPU %d got hotplugged\n", pr->id);
> 
> And this.  The caller (acpi_processor_get_info()) has an acpi_device
> *, so we should be able to use it here.

I think pr_info() is fine since it is a normal message and already has
CPU number in the message.


Thanks for the review!
-Toshi


> >         pr->flags.need_hotplug_init = 1;
> >
> >         return AE_OK;
> > --
> > 1.7.7.6
> >

Re: [PATCH v3 3/4] ACPI: Update Memory hotplug messages

[Toshi Kani]

On Thu, 2012-07-26 at 13:23 -0600, Bjorn Helgaas wrote:
> On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> > Updated Memory hotplug log messages with acpi_pr_<level>()
> > and pr_<level>().
> >
> > Signed-off-by: Toshi Kani <toshi.kani@hp.com>
> > ---
> >  drivers/acpi/acpi_memhotplug.c |   24 ++++++++++++------------
> >  1 files changed, 12 insertions(+), 12 deletions(-)
> >
> > diff --git a/drivers/acpi/acpi_memhotplug.c b/drivers/acpi/acpi_memhotplug.c
> > index 06c55cd..dcc8f4d 100644
> > --- a/drivers/acpi/acpi_memhotplug.c
> > +++ b/drivers/acpi/acpi_memhotplug.c
> > @@ -170,7 +170,7 @@ acpi_memory_get_device(acpi_handle handle,
> >         /* Get the parent device */
> >         result = acpi_bus_get_device(phandle, &pdevice);
> >         if (result) {
> > -               printk(KERN_WARNING PREFIX "Cannot get acpi bus device");
> > +               acpi_pr_warn(phandle, "Cannot get acpi bus device\n");
> >                 return -EINVAL;
> >         }
> >
> > @@ -180,14 +180,14 @@ acpi_memory_get_device(acpi_handle handle,
> >          */
> >         result = acpi_bus_add(&device, pdevice, handle, ACPI_BUS_TYPE_DEVICE);
> >         if (result) {
> > -               printk(KERN_WARNING PREFIX "Cannot add acpi bus");
> > +               acpi_pr_warn(handle, "Cannot add acpi bus\n");
> >                 return -EINVAL;
> >         }
> >
> >        end:
> >         *mem_device = acpi_driver_data(device);
> >         if (!(*mem_device)) {
> > -               printk(KERN_ERR "\n driver data not found");
> > +               acpi_pr_err(handle, "driver data not found\n");
> 
> acpi_driver_data() requires a valid acpi_device *, so dev_err() should
> work here.

Agreed. Changed to use dev_err().

> 
> >                 return -ENODEV;
> >         }
> >
> > @@ -224,7 +224,7 @@ static int acpi_memory_enable_device(struct acpi_memory_device *mem_device)
> >         /* Get the range from the _CRS */
> >         result = acpi_memory_get_device_resources(mem_device);
> >         if (result) {
> > -               printk(KERN_ERR PREFIX "get_device_resources failed\n");
> > +               pr_err(PREFIX "get_device_resources failed\n");
> 
> And here.

Changed to use dev_err().

> 
> >                 mem_device->state = MEMORY_INVALID_STATE;
> >                 return result;
> >         }
> > @@ -257,7 +257,7 @@ static int acpi_memory_enable_device(struct acpi_memory_device *mem_device)
> >                 num_enabled++;
> >         }
> >         if (!num_enabled) {
> > -               printk(KERN_ERR PREFIX "add_memory failed\n");
> > +               acpi_pr_err(mem_device->device->handle, "add_memory failed\n");
> 
> And here.

Changed to use dev_err().

> 
> >                 mem_device->state = MEMORY_INVALID_STATE;
> >                 return -EINVAL;
> >         }
> > @@ -353,7 +353,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
> >                         ACPI_DEBUG_PRINT((ACPI_DB_INFO,
> >                                           "\nReceived DEVICE CHECK notification for device\n"));
> >                 if (acpi_memory_get_device(handle, &mem_device)) {
> > -                       printk(KERN_ERR PREFIX "Cannot find driver data\n");
> > +                       acpi_pr_err(handle, "Cannot find driver data\n");
> >                         break;
> >                 }
> >
> > @@ -361,7 +361,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
> >                         break;
> >
> >                 if (acpi_memory_enable_device(mem_device)) {
> > -                       pr_err(PREFIX "Cannot enable memory device\n");
> > +                       acpi_pr_err(handle, "Cannot enable memory device\n");
> 
> And here.

No change since it is called directly from the handler.

> >                         break;
> >                 }
> >
> > @@ -373,12 +373,12 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
> >                                   "\nReceived EJECT REQUEST notification for device\n"));
> >
> >                 if (acpi_bus_get_device(handle, &device)) {
> > -                       printk(KERN_ERR PREFIX "Device doesn't exist\n");
> > +                       acpi_pr_err(handle, "Device doesn't exist\n");
> >                         break;
> >                 }
> >                 mem_device = acpi_driver_data(device);
> >                 if (!mem_device) {
> > -                       printk(KERN_ERR PREFIX "Driver Data is NULL\n");
> > +                       acpi_pr_err(handle, "Driver Data is NULL\n");
> 
> And here.

No change since it is called directly from the handler.

> >                         break;
> >                 }
> >
> > @@ -389,7 +389,7 @@ static void acpi_memory_device_notify(acpi_handle handle, u32 event, void *data)
> >                  *      with generic sysfs driver
> >                  */
> >                 if (acpi_memory_disable_device(mem_device)) {
> > -                       pr_err(PREFIX "Disable memory device\n");
> > +                       acpi_pr_err(handle, "Disable memory device\n");
> 
> And here.  (What is this message supposed to mean, anyway?)

I changed the message to "Failed to remove memory device\n". This case
is failed in off-lining or ejecting the memory.

> >                         /*
> >                          * If _EJ0 was called but failed, _OST is not
> >                          * necessary.
> > @@ -449,7 +449,7 @@ static int acpi_memory_device_add(struct acpi_device *device)
> >         /* Set the device state */
> >         mem_device->state = MEMORY_POWER_ON_STATE;
> >
> > -       printk(KERN_DEBUG "%s \n", acpi_device_name(device));
> > +       pr_debug("%s\n", acpi_device_name(device));
> 
> And here.  This message looks dubious anyway.

It kept it as is since it is a debug message anyway. I expect it will be
removed eventually.

> >
> >         /*
> >          * Early boot code has recognized memory area by EFI/E820.
> > @@ -464,7 +464,7 @@ static int acpi_memory_device_add(struct acpi_device *device)
> >                 /* call add_memory func */
> >                 result = acpi_memory_enable_device(mem_device);
> >                 if (result)
> > -                       printk(KERN_ERR PREFIX
> > +                       acpi_pr_err(device->handle,
> >                                 "Error in acpi_memory_enable_device\n");
> 
> And here.

Changed to use dev_err().


Thanks!
-Toshi


> 
> >         }
> >         return result;
> > --
> > 1.7.7.6
> >

Re: [PATCH v3 4/4] ACPI: Update Container hotplug messages

[Toshi Kani]

On Thu, 2012-07-26 at 13:23 -0600, Bjorn Helgaas wrote:
> On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> > Updated Container hotplug log messages with acpi_pr_<level>()
> > and pr_<level>().
> >
> > Signed-off-by: Toshi Kani <toshi.kani@hp.com>
> > ---
> >  drivers/acpi/container.c |    6 +++---
> >  1 files changed, 3 insertions(+), 3 deletions(-)
> >
> > diff --git a/drivers/acpi/container.c b/drivers/acpi/container.c
> > index 01a986d..643e962 100644
> > --- a/drivers/acpi/container.c
> > +++ b/drivers/acpi/container.c
> > @@ -99,7 +99,7 @@ static int acpi_container_add(struct acpi_device *device)
> >
> >
> >         if (!device) {
> > -               printk(KERN_ERR PREFIX "device is NULL\n");
> > +               pr_err(PREFIX "device is NULL\n");
> >                 return -EINVAL;
> >         }
> 
> This whole "if (!device)" check and the printk should be deleted.  If
> the ACPI core calls .add() with a null acpi_device pointer, it's a
> core bug, and it's better to take the oops and get the backtrace.

Agreed. Delete the check.

> >
> > @@ -164,7 +164,7 @@ static void container_notify_cb(acpi_handle handle, u32 type, void *context)
> >         case ACPI_NOTIFY_BUS_CHECK:
> >                 /* Fall through */
> >         case ACPI_NOTIFY_DEVICE_CHECK:
> > -               printk(KERN_WARNING "Container driver received %s event\n",
> > +               pr_warn("Container driver received %s event\n",
> >                        (type == ACPI_NOTIFY_BUS_CHECK) ?
> >                        "ACPI_NOTIFY_BUS_CHECK" : "ACPI_NOTIFY_DEVICE_CHECK");
> 
> This message looks dubious.  Receiving this event should be a normal
> occurrence, so the message might be useful for debugging, but doesn't
> seem like a KERN_WARNING event for the user.

Changed to pr_debug() for now.


Thanks!
-Toshi


> >
> > @@ -185,7 +185,7 @@ static void container_notify_cb(acpi_handle handle, u32 type, void *context)
> >
> >                 result = container_device_add(&device, handle);
> >                 if (result) {
> > -                       pr_warn("Failed to add container\n");
> > +                       acpi_pr_warn(handle, "Failed to add container\n");
> >                         break;
> >                 }
> >
> > --
> > 1.7.7.6
> >

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Toshi Kani]

On Thu, 2012-07-26 at 15:50 -0600, Bjorn Helgaas wrote:
> On Thu, Jul 26, 2012 at 3:43 PM, Joe Perches <joe@perches.com> wrote:
> > On Thu, 2012-07-26 at 15:37 -0600, Bjorn Helgaas wrote:
> >>     PNP0C01:00: new device for \_SB_.PCI0.ISA_.MBIO
> >>
> >> I fiddled with this a while ago; it would look something like this:
> > []
> >> +static noinline_for_stack
> >> +char *acpi_name_string(char *buf, char *end, acpi_handle handle,
> >> +                    struct printf_spec spec, const char *fmt)
> >> +{
> >> +     acpi_status status;
> >> +     struct acpi_buffer buffer = { ACPI_ALLOCATE_BUFFER, NULL };
> >> +     u32 type = ACPI_SINGLE_NAME;
> >> +     char *p = buf;
> >> +
> >> +     if (fmt[0] == 'A')
> >> +             type = ACPI_FULL_PATHNAME;
> >
> > maybe if (fmt[1] == 'f')
> >
> >> @@ -982,6 +1007,9 @@ char *pointer(const char *fmt, char *buf, char *end, void *ptr,
> >>       }
> >>
> >>       switch (*fmt) {
> >> +     case 'A':
> >> +     case 'a':
> >> +             return acpi_name_string(buf, end, ptr, spec, fmt);
> >
> > There are only so many letters, it might be better to
> > just use 'a' and another 'f' after that if necessary
> > for "full".
> >
> > And of course that should be #ifdef'd too
> 
> Yes.  I'm hesitant about this approach in general, because I don't
> think printing the ACPI path is something we should be doing often.
> It's not like a struct resource or a MAC address, where there are
> dozens or hundreds of users.  I really think we should only print ACPI
> paths in one or two places, so adding a %p extension would waste a
> letter and encourage the wrong behavior.

That's a good point.  I agree.  So, let's continue to use
acpi_pr_<level>() for printing ACPI device path.  The use of this
interface is limited anyway. 

Thanks,
-Toshi

Re: [PATCH v3 1/4] ACPI: Add acpi_pr_<level>() interfaces

[Toshi Kani]

On Thu, 2012-07-26 at 14:57 -0700, Joe Perches wrote:
> On Thu, 2012-07-26 at 15:50 -0600, Bjorn Helgaas wrote:
> > On Thu, Jul 26, 2012 at 3:43 PM, Joe Perches <joe@perches.com> wrote:
> > > On Thu, 2012-07-26 at 15:37 -0600, Bjorn Helgaas wrote:
> > >>     PNP0C01:00: new device for \_SB_.PCI0.ISA_.MBIO
> > >>
> > >> I fiddled with this a while ago; it would look something like this:
> > > []
> > >> +static noinline_for_stack
> > >> +char *acpi_name_string(char *buf, char *end, acpi_handle handle,
> > >> +                    struct printf_spec spec, const char *fmt)
> []
> > Yes.  I'm hesitant about this approach in general, because I don't
> > think printing the ACPI path is something we should be doing often.
> > It's not like a struct resource or a MAC address, where there are
> > dozens or hundreds of users.  I really think we should only print ACPI
> > paths in one or two places, so adding a %p extension would waste a
> > letter and encourage the wrong behavior.
> 
> I don't much care for adding ACPI specific calls to vsprintf
> as acpi is supposed to be OS generic anyway.
> 
> I don't think there's anything wrong with Toshi's approach.
> Anyone that looks for speed in a logging message is looking
> for an oddly fitting thing.  Tracing sure, but logging?

Fully agreed!  One cannot use printk in performance path.

Thanks,
-Toshi


> I also don't see anything wrong with renaming it to just
> acpi_<level>, but that's a different discussion.
> 
> cheers, Joe
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

Re: [PATCH v3 2/4] ACPI: Update CPU hotplug messages

[Bjorn Helgaas]

On Thu, Jul 26, 2012 at 8:39 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> On Thu, 2012-07-26 at 13:23 -0600, Bjorn Helgaas wrote:
>> On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:

>> > @@ -560,8 +565,7 @@ static int __cpuinit acpi_processor_add(struct acpi_device *device)
>> >          */
>> >         if (per_cpu(processor_device_array, pr->id) != NULL &&
>> >             per_cpu(processor_device_array, pr->id) != device) {
>> > -               printk(KERN_WARNING "BIOS reported wrong ACPI id "
>> > -                       "for the processor\n");
>> > +               pr_warn("BIOS reported wrong ACPI id for the processor\n");
>>
>> And this.
>
> Changed to use dev_warn().

Is there additional information you could print here, like the pr->id?
 I don't understand the data structures here, so maybe there isn't.

>> > @@ -727,17 +731,19 @@ static void acpi_processor_hotplug_notify(acpi_handle handle,
>> >                                   "received ACPI_NOTIFY_EJECT_REQUEST\n"));
>> >
>> >                 if (acpi_bus_get_device(handle, &device)) {
>> > -                       pr_err(PREFIX "Device don't exist, dropping EJECT\n");
>> > +                       acpi_pr_err(handle,
>> > +                               "Device don't exist, dropping EJECT\n");
>> >                         break;
>> >                 }
>> >                 if (!acpi_driver_data(device)) {
>> > -                       pr_err(PREFIX "Driver data is NULL, dropping EJECT\n");
>> > +                       acpi_pr_err(handle,
>> > +                               "Driver data is NULL, dropping EJECT\n");
>>
>> And this.
>
> No change since it is called directly from the handler.

True, but by this point, we have a valid acpi_device *, don't we?  We
called acpi_driver_data(device), which requires "device" to be valid.

>> >                         break;
>> >                 }
>> >
>> >                 ej_event = kmalloc(sizeof(*ej_event), GFP_KERNEL);
>> >                 if (!ej_event) {
>> > -                       pr_err(PREFIX "No memory, dropping EJECT\n");
>> > +                       acpi_pr_err(handle, "No memory, dropping EJECT\n");
>>
>> And this.
>
> No change since it is called directly from the handler.
>
>> >                         break;
>> >                 }
>> >
>> > @@ -847,7 +853,7 @@ static acpi_status acpi_processor_hotadd_init(struct acpi_processor *pr)
>> >          * and do it when the CPU gets online the first time
>> >          * TBD: Cleanup above functions and try to do this more elegant.
>> >          */
>> > -       printk(KERN_INFO "CPU %d got hotplugged\n", pr->id);
>> > +       pr_info("CPU %d got hotplugged\n", pr->id);
>>
>> And this.  The caller (acpi_processor_get_info()) has an acpi_device
>> *, so we should be able to use it here.
>
> I think pr_info() is fine since it is a normal message and already has
> CPU number in the message.

Is there another message that correlates the device name
("ACPI0007:xx") with the CPU number?  That correlation seems useful.
My mindset is that a driver should *always* use dev_<level>() when
possible, but I won't belabor the point.

Bjorn

Re: [PATCH v3 2/4] ACPI: Update CPU hotplug messages

[Toshi Kani]

On Fri, 2012-07-27 at 10:05 -0600, Bjorn Helgaas wrote:
> On Thu, Jul 26, 2012 at 8:39 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> > On Thu, 2012-07-26 at 13:23 -0600, Bjorn Helgaas wrote:
> >> On Wed, Jul 25, 2012 at 5:12 PM, Toshi Kani <toshi.kani@hp.com> wrote:
> 
> >> > @@ -560,8 +565,7 @@ static int __cpuinit acpi_processor_add(struct acpi_device *device)
> >> >          */
> >> >         if (per_cpu(processor_device_array, pr->id) != NULL &&
> >> >             per_cpu(processor_device_array, pr->id) != device) {
> >> > -               printk(KERN_WARNING "BIOS reported wrong ACPI id "
> >> > -                       "for the processor\n");
> >> > +               pr_warn("BIOS reported wrong ACPI id for the processor\n");
> >>
> >> And this.
> >
> > Changed to use dev_warn().
> 
> Is there additional information you could print here, like the pr->id?
>  I don't understand the data structures here, so maybe there isn't.

Good point.  Yes, we should print pr->id so that we can check if the id
value is wrong.  I will make this change later since I would likely
touch this file again. :)  For now, I'd like to settle the patches
unless there is a major issue.

> >> > @@ -727,17 +731,19 @@ static void acpi_processor_hotplug_notify(acpi_handle handle,
> >> >                                   "received ACPI_NOTIFY_EJECT_REQUEST\n"));
> >> >
> >> >                 if (acpi_bus_get_device(handle, &device)) {
> >> > -                       pr_err(PREFIX "Device don't exist, dropping EJECT\n");
> >> > +                       acpi_pr_err(handle,
> >> > +                               "Device don't exist, dropping EJECT\n");
> >> >                         break;
> >> >                 }
> >> >                 if (!acpi_driver_data(device)) {
> >> > -                       pr_err(PREFIX "Driver data is NULL, dropping EJECT\n");
> >> > +                       acpi_pr_err(handle,
> >> > +                               "Driver data is NULL, dropping EJECT\n");
> >>
> >> And this.
> >
> > No change since it is called directly from the handler.
> 
> True, but by this point, we have a valid acpi_device *, don't we?  We
> called acpi_driver_data(device), which requires "device" to be valid.

Right.  But we need to print ACPI device path in order to be able to
analyze from the log file.  Hence, I am keeping acpi_pr_<level> in the
error paths of the handler itself.  Any subsequent functions call
dev_<level>() when device is valid.  In this particular case,
acpi_driver_data() does not call dev_<level>() when its return value is
NULL, but most other cases are changed to call dev_<level>().

> >> >                         break;
> >> >                 }
> >> >
> >> >                 ej_event = kmalloc(sizeof(*ej_event), GFP_KERNEL);
> >> >                 if (!ej_event) {
> >> > -                       pr_err(PREFIX "No memory, dropping EJECT\n");
> >> > +                       acpi_pr_err(handle, "No memory, dropping EJECT\n");
> >>
> >> And this.
> >
> > No change since it is called directly from the handler.
> >
> >> >                         break;
> >> >                 }
> >> >
> >> > @@ -847,7 +853,7 @@ static acpi_status acpi_processor_hotadd_init(struct acpi_processor *pr)
> >> >          * and do it when the CPU gets online the first time
> >> >          * TBD: Cleanup above functions and try to do this more elegant.
> >> >          */
> >> > -       printk(KERN_INFO "CPU %d got hotplugged\n", pr->id);
> >> > +       pr_info("CPU %d got hotplugged\n", pr->id);
> >>
> >> And this.  The caller (acpi_processor_get_info()) has an acpi_device
> >> *, so we should be able to use it here.
> >
> > I think pr_info() is fine since it is a normal message and already has
> > CPU number in the message.
> 
> Is there another message that correlates the device name
> ("ACPI0007:xx") with the CPU number?  That correlation seems useful.
> My mindset is that a driver should *always* use dev_<level>() when
> possible, but I won't belabor the point.

That's a good point.  This CPU number is used for cpu# file
under /sys/devices/system/cpu, but I do not think there is a good way to
correlate this number to the device name.  This is also the case for all
CPUs launched at boot-time.  At boot-time, all CPUs are launched from
the MADT table, and the code has no knowledge about processor objects.
Typically, cpu# and device instance# are same at boot-time, though.  I
will think about this issue further.

Thanks,
-Toshi

> 
> Bjorn