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

[Bjorn Helgaas <bhelgaas@google.com>]

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);