Xen devel - Nov 2013 - [PATCH 0/5] Printk symbol specifier

This series implements %ps and %pS, in the same way as Linux.

The first patch adds support to vsnprintf().  I audited all current uses of %p
and none would trigger the new codepath.

I was a little unsure about the best way of adding in support, so the patch is
a little RFC.

I used a switch statement to make it easier to add in further custom %p
support in the future (print hex buffer looks interesting), but forwent the
default case to reduce code motion.

The 128 byte namebuf on the stack is a tad unsavoury, but less so than a static
buffer with spinlock (which should have been included in the set of spinlocks
busted by console_force_unlock(), as printing symbols is very common on a
crash path).

The recursive call to snprintf is the least bad option available.  For the
basic string, I have copied the loop from the %s handler to save the
recursion.  Finally, all of the width specifier are ignored; I cant see a
reasonable usecase for them.


The second and third patches replace all uses of print_symbol() with %ps/%pS,
for x86 and arm respectively.  Most replacements are straight replacements,
but I have taken the opportunity to slightly cleanup the stack tracing code.
When two CPUs are racing at printing a stack, they contend on the console
spinlock, resulting in interleaving across end of the partial strings.  Now,
each full line of the stack trace is printed from a single printk(), so the
interleaving will occur at the line boundaries rather than mid-line
boundaries.

The fourth patch removes print_symbol() and friends, now that the
functionality has been completely replaced.

The fifth patch is not intended for committing, but for people wishing to test
and verify some of the boundary conditions.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Ian Campbell <ian.campbell@citrix.com>
CC: Stefano Stabellini <stefano.stabellini@citrix.com>
CC: Tim Deegan <tim@xen.org>

-- 
1.7.10.4

Introduce the %ps and %pS format options for printing a symbol.

  %ps will print the symbol name along
  %pS will print the symbol name + offset / size

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
---
 xen/common/vsprintf.c |   42 ++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 42 insertions(+)

diff --git a/xen/common/vsprintf.c b/xen/common/vsprintf.c
index 95bf85d..e5fb2e1 100644
--- a/xen/common/vsprintf.c
+++ b/xen/common/vsprintf.c
@@ -17,6 +17,7 @@
  */
 
 #include <xen/ctype.h>
+#include <xen/symbols.h>
 #include <xen/lib.h>
 #include <asm/div64.h>
 #include <asm/page.h>
@@ -392,6 +393,47 @@ int vsnprintf(char *buf, size_t size, const char *fmt,
va_list args)
             continue;
 
         case ''p'':
+
+            /*
+             * Custom %p suffixes, compatible with Linux.
+             * See Linux:Documentation/printk-formats.txt
+             */
+            switch ( fmt[1] )
+            {
+            case ''s'': /* Symbol name */
+            case ''S'': /* Symbol name with offset and size */
+            {
+                unsigned long sym_size, sym_offset,
+                    addr = (unsigned long)va_arg(args, void *);
+                char namebuf[KSYM_NAME_LEN+1];
+
+                s = symbols_lookup(addr, &sym_size, &sym_offset,
namebuf);
+
+                if ( !s || fmt[1] == ''s'' )
+                {
+                    if ( !s )
+                        s = "???";
+
+                    len = strnlen(s, KSYM_NAME_LEN);
+
+                    for ( i = 0; i < len; ++i )
+                    {
+                        if ( str <= end )
+                            *str = *s;
+                        ++str; ++s;
+                    }
+                }
+                else
+                    str += snprintf(str, end - str + 1,
"%s+%#lx/%#lx",
+                                    s, sym_offset, sym_size);
+
+                fmt++;
+                continue;
+            }
+
+            /* Fall through to basic %p */
+            }
+
             if (field_width == -1) {
                 field_width = 2*sizeof(void *);
                 flags |= ZEROPAD;
-- 
1.7.10.4

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
---
 xen/arch/x86/irq.c          |    7 ++-----
 xen/arch/x86/time.c         |    3 +--
 xen/arch/x86/traps.c        |   30 ++++++++++--------------------
 xen/arch/x86/x86_64/traps.c |    2 +-
 xen/common/timer.c          |    6 +++---
 5 files changed, 17 insertions(+), 31 deletions(-)

diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c
index a984bda..c2e5629 100644
--- a/xen/arch/x86/irq.c
+++ b/xen/arch/x86/irq.c
@@ -2276,7 +2276,7 @@ static void dump_irqs(unsigned char key)
             printk("\n");
         }
         else if ( desc->action )
-            print_symbol("%s\n", (unsigned
long)desc->action->handler);
+            printk("%ps()\n", _p(desc->action->handler));
         else
             printk("mapped, unbound\n");
 
@@ -2288,10 +2288,7 @@ static void dump_irqs(unsigned char key)
     printk("Direct vector information:\n");
     for ( i = FIRST_DYNAMIC_VECTOR; i < NR_VECTORS; ++i )
         if ( direct_apic_vector[i] )
-        {
-            printk("   %#02x -> ", i);
-            print_symbol("%s\n", (unsigned
long)direct_apic_vector[i]);
-        }
+            printk("   %#02x -> %ps()\n", i,
_p(direct_apic_vector[i]));
 
     dump_ioapic_irq_info();
 }
diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index c1bbd50..daade00 100644
--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -1475,8 +1475,7 @@ static int
_disable_pit_irq(void(*hpet_broadcast_setup)(void))
         {
             if ( xen_cpuidle > 0 )
             {
-                print_symbol("%s() failed, turning to PIT
broadcast\n",
-                             (unsigned long)hpet_broadcast_setup);
+                printk("hpet_broadcast_setup() failed, turning to PIT
broadcast\n");
                 return -1;
             }
             ret = 0;
diff --git a/xen/arch/x86/traps.c b/xen/arch/x86/traps.c
index 77c200b..0e3c6e3 100644
--- a/xen/arch/x86/traps.c
+++ b/xen/arch/x86/traps.c
@@ -198,19 +198,14 @@ static void show_trace(struct cpu_user_regs *regs)
 {
     unsigned long *stack = ESP_BEFORE_EXCEPTION(regs), addr;
 
-    printk("Xen call trace:\n   ");
-
-    printk("[<%p>]", _p(regs->eip));
-    print_symbol(" %s\n   ", regs->eip);
+    printk("Xen call trace:\n"
+           "   [<%p>] %pS\n", _p(regs->eip),
_p(regs->eip));
 
     while ( ((long)stack & (STACK_SIZE-BYTES_PER_LONG)) != 0 )
     {
         addr = *stack++;
         if ( is_active_kernel_text(addr) )
-        {
-            printk("[<%p>]", _p(addr));
-            print_symbol(" %s\n   ", addr);
-        }
+            printk("   [<%p>] %pS\n", _p(addr), _p(addr));
     }
 
     printk("\n");
@@ -222,8 +217,6 @@ static void show_trace(struct cpu_user_regs *regs)
 {
     unsigned long *frame, next, addr, low, high;
 
-    printk("Xen call trace:\n   ");
-
     /*
      * If RIP is not pointing into hypervisor code then someone may have
      * called into oblivion. Peek to see if they left a return address at
@@ -232,8 +225,9 @@ static void show_trace(struct cpu_user_regs *regs)
     addr = is_active_kernel_text(regs->eip) ||
            !is_active_kernel_text(*ESP_BEFORE_EXCEPTION(regs)) ?
            regs->eip : *ESP_BEFORE_EXCEPTION(regs);
-    printk("[<%p>]", _p(addr));
-    print_symbol(" %s\n   ", addr);
+
+    printk("Xen call trace:\n"
+           "   [<%p>] %pS\n", _p(addr), _p(addr));
 
     /* Bounds for range of valid frame pointer. */
     low  = (unsigned long)(ESP_BEFORE_EXCEPTION(regs) - 2);
@@ -269,8 +263,7 @@ static void show_trace(struct cpu_user_regs *regs)
             addr  = frame[1];
         }
 
-        printk("[<%p>]", _p(addr));
-        print_symbol(" %s\n   ", addr);
+        printk("   [<%p>] %pS\n", _p(addr), _p(addr));
 
         low = (unsigned long)&frame[2];
     }
@@ -338,10 +331,7 @@ void show_stack_overflow(unsigned int cpu, unsigned long
esp)
     {
         addr = *stack++;
         if ( is_active_kernel_text(addr) )
-        {
-            printk("%p: [<%p>]", stack, _p(addr));
-            print_symbol(" %s\n   ", addr);
-        }
+            printk("%p: [<%p>] %pS\n", stack, _p(addr),
_p(addr));
     }
 
     printk("\n");
@@ -3755,8 +3745,8 @@ void asm_domain_crash_synchronous(unsigned long addr)
     if ( addr == 0 )
         addr = this_cpu(last_extable_addr);
 
-    printk("domain_crash_sync called from entry.S: fault at %p ",
_p(addr));
-    print_symbol("%s\n", addr);
+    printk("domain_crash_sync called from entry.S: fault at %p
%pS\n",
+           _p(addr), _p(addr));
 
     __domain_crash_synchronous();
 }
diff --git a/xen/arch/x86/x86_64/traps.c b/xen/arch/x86/x86_64/traps.c
index 0316d7c..ae93539 100644
--- a/xen/arch/x86/x86_64/traps.c
+++ b/xen/arch/x86/x86_64/traps.c
@@ -49,7 +49,7 @@ static void _show_registers(
 
     printk("RIP:    %04x:[<%016lx>]", regs->cs,
regs->rip);
     if ( context == CTXT_hypervisor )
-        print_symbol(" %s", regs->rip);
+        printk(" %pS", _p(regs->rip));
     printk("\nRFLAGS: %016lx   ", regs->rflags);
     if ( (context == CTXT_pv_guest) && v && v->vcpu_info )
         printk("EM: %d   ", !!vcpu_info(v, evtchn_upcall_mask));
diff --git a/xen/common/timer.c b/xen/common/timer.c
index 9ed74e9..eff9c26 100644
--- a/xen/common/timer.c
+++ b/xen/common/timer.c
@@ -511,9 +511,9 @@ s_time_t align_timer(s_time_t firsttick, uint64_t period)
 
 static void dump_timer(struct timer *t, s_time_t now)
 {
-    printk("  ex=%8"PRId64"us timer=%p cb=%p(%p)",
-           (t->expires - now) / 1000, t, t->function, t->data);
-    print_symbol(" %s\n", (unsigned long)t->function);
+    printk("  ex=%8"PRId64"us timer=%p cb=%p(%p) %ps()\n",
+           (t->expires - now) / 1000, t, t->function, t->data,
+           _p(t->function));
 }
 
 static void dump_timerq(unsigned char key)
-- 
1.7.10.4

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Ian Campbell <ian.campbell@citrix.com>
CC: Stefano Stabellini <stefano.stabellini@citrix.com>
CC: Tim Deegan <tim@xen.org>
---
 xen/arch/arm/traps.c |   15 ++++++---------
 1 file changed, 6 insertions(+), 9 deletions(-)

diff --git a/xen/arch/arm/traps.c b/xen/arch/arm/traps.c
index 4c0fc32..532b0c8 100644
--- a/xen/arch/arm/traps.c
+++ b/xen/arch/arm/traps.c
@@ -387,7 +387,7 @@ static void show_registers_32(struct cpu_user_regs *regs,
 #else
     printk("PC:     %08"PRIx32, regs->pc);
     if ( !guest_mode )
-        print_symbol(" %s", regs->pc);
+        printk(" %pS", _p(regs->pc));
     printk("\n");
 #endif
     printk("CPSR:   %08"PRIx32" MODE:%s\n", regs->cpsr,
@@ -462,7 +462,7 @@ static void show_registers_64(struct cpu_user_regs *regs,
 
     printk("PC:     %016"PRIx64, regs->pc);
     if ( !guest_mode )
-        print_symbol(" %s", regs->pc);
+        printk(" %pS", _p(regs->pc));
     printk("\n");
     printk("LR:     %016"PRIx64"\n", regs->lr);
     if ( guest_mode )
@@ -727,12 +727,10 @@ static void show_trace(struct cpu_user_regs *regs)
 {
     register_t *frame, next, addr, low, high;
 
-    printk("Xen call trace:\n   ");
+    printk("Xen call trace:\n");
 
-    printk("[<%p>]", _p(regs->pc));
-    print_symbol(" %s (PC)\n   ", regs->pc);
-    printk("[<%p>]", _p(regs->lr));
-    print_symbol(" %s (LR)\n   ", regs->lr);
+    printk("   [<%p>] %pS (PC)\n", _p(regs->pc),
_p(regs->pc));
+    printk("   [<%p>] %pS (LR)\n", _p(regs->lr),
_p(regs->lr));
 
     /* Bounds for range of valid frame pointer. */
     low  = (register_t)(STACK_BEFORE_EXCEPTION(regs));
@@ -752,8 +750,7 @@ static void show_trace(struct cpu_user_regs *regs)
         next  = frame[0];
         addr  = frame[1];
 
-        printk("[<%p>]", _p(addr));
-        print_symbol(" %s\n   ", addr);
+        printk("   [<%p>] %pS\n", _p(addr), _p(addr));
 
         low = (register_t)&frame[1];
     }
-- 
1.7.10.4

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
---
 xen/common/symbols.c      |   26 --------------------------
 xen/include/xen/symbols.h |   23 -----------------------
 2 files changed, 49 deletions(-)

diff --git a/xen/common/symbols.c b/xen/common/symbols.c
index 83b2b58..45941e1 100644
--- a/xen/common/symbols.c
+++ b/xen/common/symbols.c
@@ -148,29 +148,3 @@ const char *symbols_lookup(unsigned long addr,
     *offset = addr - symbols_address(low);
     return namebuf;
 }
-
-/* Replace "%s" in format with address, or returns -errno. */
-void __print_symbol(const char *fmt, unsigned long address)
-{
-    const char *name;
-    unsigned long offset, size, flags;
-
-    static DEFINE_SPINLOCK(lock);
-    static char namebuf[KSYM_NAME_LEN+1];
-#define BUFFER_SIZE sizeof("%s+%#lx/%#lx [%s]") + KSYM_NAME_LEN + \
-			2*(BITS_PER_LONG*3/10) + 1
-    static char buffer[BUFFER_SIZE];
-
-    spin_lock_irqsave(&lock, flags);
-
-    name = symbols_lookup(address, &size, &offset, namebuf);
-
-    if (!name)
-        snprintf(buffer, BUFFER_SIZE, "???");
-    else
-        snprintf(buffer, BUFFER_SIZE, "%s+%#lx/%#lx", name, offset,
size);
-
-    printk(fmt, buffer);
-
-    spin_unlock_irqrestore(&lock, flags);
-}
diff --git a/xen/include/xen/symbols.h b/xen/include/xen/symbols.h
index 37cf6bf..87cd77d 100644
--- a/xen/include/xen/symbols.h
+++ b/xen/include/xen/symbols.h
@@ -11,27 +11,4 @@ const char *symbols_lookup(unsigned long addr,
                            unsigned long *offset,
                            char *namebuf);
 
-/* Replace "%s" in format with address, if found */
-void __print_symbol(const char *fmt, unsigned long address);
-
-/* This macro allows us to keep printk typechecking */
-static void __check_printsym_format(const char *fmt, ...)
-    __attribute__((format(printf,1,2)));
-    static inline void __check_printsym_format(const char *fmt, ...)
-{
-}
-
-#if 0
-#define print_fn_descriptor_symbol(fmt, addr)	\
-	print_symbol(fmt, *(unsigned long *)addr)
-#else
-#define print_fn_descriptor_symbol(fmt, addr) print_symbol(fmt, addr)
-#endif
-
-#define print_symbol(fmt, addr)			\
-do {						\
-	__check_printsym_format(fmt, "");	\
-	__print_symbol(fmt, addr);		\
-} while(0)
-
 #endif /*_XEN_SYMBOLS_H*/
-- 
1.7.10.4

---
 xen/arch/x86/irq.c |   36 ++++++++++++++++++++++++++++++++++++
 1 file changed, 36 insertions(+)

diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c
index c2e5629..6a447ff 100644
--- a/xen/arch/x86/irq.c
+++ b/xen/arch/x86/irq.c
@@ -2485,3 +2485,39 @@ bool_t hvm_domain_use_pirq(const struct domain *d, const
struct pirq *pirq)
     return is_hvm_domain(d) && pirq &&
            pirq->arch.hvm.emuirq != IRQ_UNBOUND; 
 }
+
+static void test_printk(unsigned char key)
+{
+    char buffer[8] = { 0 };
+    char buffer2[3] = { 0 };
+
+    printk("In %s()\n", __func__);
+    printk("Some symbols: ''%ps''
''%pS''\n", _p(printk), _p(printk));
+    printk("More symbols: ''%ps''
''%pS''\n", _p(test_printk), _p(test_printk));
+    printk("Invalid: ''%ps''
''%pS''\n", _p(NULL), _p(NULL));
+    printk("Partial: ''%ps''
''%pS''\n", _p(((unsigned long)test_printk + 0x20)),
+           _p(((unsigned long)test_printk + 0x20)));
+
+    snprintf(buffer, sizeof buffer, "%pS", _p(test_printk));
+    printk("Test printing into 8 byte buffer
''%s''\n", buffer);
+
+    snprintf(buffer, sizeof buffer, "%ps", _p(test_printk));
+    printk("Test printing into 8 byte buffer
''%s''\n", buffer);
+
+    snprintf(buffer2, sizeof buffer2, "%ps",
+             _p(((unsigned long)test_printk + 0x20)));
+    printk("Test printing into 3 byte buffer
''%s''\n", buffer2);
+}
+
+static struct keyhandler test_printk_keyhandler = {
+    .diagnostic = 1,
+    .u.fn = test_printk,
+    .desc = "Test new printk formatting options"
+};
+
+static int __init setup_test_printk(void)
+{
+    register_keyhandler(''6'', &test_printk_keyhandler);
+    return 0;
+}
+__initcall(setup_test_printk);
-- 
1.7.10.4

>>> On 04.11.13 at 11:55, Andrew Cooper
<andrew.cooper3@citrix.com> wrote:
> @@ -392,6 +393,47 @@ int vsnprintf(char *buf, size_t size, const char *fmt,
va_list args)
>              continue;
>  
>          case ''p'':
> +
> +            /*
> +             * Custom %p suffixes, compatible with Linux.
> +             * See Linux:Documentation/printk-formats.txt
> +             */
> +            switch ( fmt[1] )
> +            {
> +            case ''s'': /* Symbol name */
> +            case ''S'': /* Symbol name with offset and
size */
> +            {
> +                unsigned long sym_size, sym_offset,
> +                    addr = (unsigned long)va_arg(args, void *);
> +                char namebuf[KSYM_NAME_LEN+1];
> +
> +                s = symbols_lookup(addr, &sym_size, &sym_offset,
namebuf);
> +
> +                if ( !s || fmt[1] == ''s'' )
> +                {
> +                    if ( !s )
> +                        s = "???";
> +
> +                    len = strnlen(s, KSYM_NAME_LEN);
> +
> +                    for ( i = 0; i < len; ++i )
> +                    {
> +                        if ( str <= end )
> +                            *str = *s;
> +                        ++str; ++s;
> +                    }
> +                }
> +                else
> +                    str += snprintf(str, end - str + 1,
"%s+%#lx/%#lx",
> +                                    s, sym_offset, sym_size);
> +
> +                fmt++;
> +                continue;
> +            }
> +
> +            /* Fall through to basic %p */
> +            }
> +
>              if (field_width == -1) {
>                  field_width = 2*sizeof(void *);
>                  flags |= ZEROPAD;
For the sake of future extensibility (with the code remaining
legible) this should be broken out into a pointer() function
similar (but not necessarily identical) to Linux''es. Nesting
long switch() statements isn''t really nice (I''ve got comments
on nested ones in the past even if the inner one was short).

Jan

>>> On 04.11.13 at 11:55, Andrew Cooper
<andrew.cooper3@citrix.com> wrote:
> @@ -392,6 +393,47 @@ int vsnprintf(char *buf, size_t size, const char *fmt,
va_list args)
>              continue;
>  
>          case ''p'':
> +
> +            /*
> +             * Custom %p suffixes, compatible with Linux.
> +             * See Linux:Documentation/printk-formats.txt
> +             */
> +            switch ( fmt[1] )
> +            {
> +            case ''s'': /* Symbol name */
> +            case ''S'': /* Symbol name with offset and
size */
> +            {
> +                unsigned long sym_size, sym_offset,
> +                    addr = (unsigned long)va_arg(args, void *);
> +                char namebuf[KSYM_NAME_LEN+1];
> +
> +                s = symbols_lookup(addr, &sym_size, &sym_offset,
namebuf);
> +
> +                if ( !s || fmt[1] == ''s'' )
> +                {
> +                    if ( !s )
> +                        s = "???";
Oh, and - perhaps better to print the hex value here than hide
the information on the pointer value altogether.

Jan

On Mon, 2013-11-04 at 10:55 +0000, Andrew Cooper wrote:
> Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
Acked-by: Ian Campbell <ian.campbell@citrix.com>

(assume whoever pcks up the series will commit the ARM bit too)

Hi, 

At 10:55 +0000 on 04 Nov (1383558935), Andrew Cooper
wrote:
> Introduce the %ps and %pS format options for printing a symbol.
> 
>   %ps will print the symbol name along
s/along/alone/ ?
> +
> +            /*
> +             * Custom %p suffixes, compatible with Linux.
> +             * See Linux:Documentation/printk-formats.txt
I think it would be better to copy the docs into the Xen tree (or at
least ref a specific version of linux) in case this all changes in linux.

Tim