[PATCH 1/2] x86/shadow: More consistent printing for debug messages

[PATCH 1/2] x86/shadow: More consistent printing for debug messages

[Andrew Cooper]

 * Use %pv or just d%d in preference to the multiple current ways of
   presenting the same information.
 * Use PRI_mfn instead of opencoding it.
 * Drop all explicit use of __func__ from SHADOW_{PRINTK,DEBUG}() calls.  The
   wrappers already include it.
 * Use hex rather than decimal for printing a pagefault error code.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
---
CC: Jan Beulich <JBeulich@suse.com>
CC: Tim Deegan <tim@xen.org>
CC: George Dunlap <george.dunlap@eu.citrix.com>
---
 xen/arch/x86/mm/shadow/common.c | 23 ++++++++++------------
 xen/arch/x86/mm/shadow/multi.c  | 42 ++++++++++++++++++-----------------------
 2 files changed, 28 insertions(+), 37 deletions(-)

diff --git a/xen/arch/x86/mm/shadow/common.c b/xen/arch/x86/mm/shadow/common.c
index c22362f..04ce322 100644
--- a/xen/arch/x86/mm/shadow/common.c
+++ b/xen/arch/x86/mm/shadow/common.c
@@ -723,8 +723,7 @@ static void _sh_resync(struct vcpu *v, mfn_t gmfn,
              & ~SHF_L1_ANY));
     ASSERT(!sh_page_has_multiple_shadows(mfn_to_page(gmfn)));
 
-    SHADOW_PRINTK("d=%d, v=%d, gmfn=%05lx\n",
-                  v->domain->domain_id, v->vcpu_id, mfn_x(gmfn));
+    SHADOW_PRINTK("%pv gmfn=%"PRI_mfn"\n", v, mfn_x(gmfn));
 
     /* Need to pull write access so the page *stays* in sync. */
     if ( oos_remove_write_access(v, gmfn, fixup) )
@@ -900,7 +899,7 @@ void sh_resync_all(struct vcpu *v, int skip, int this, int others)
     mfn_t *oos_snapshot = v->arch.paging.shadow.oos_snapshot;
     struct oos_fixup *oos_fixup = v->arch.paging.shadow.oos_fixup;
 
-    SHADOW_PRINTK("d=%d, v=%d\n", v->domain->domain_id, v->vcpu_id);
+    SHADOW_PRINTK("%pv\n", v);
 
     ASSERT(paging_locked_by_me(v->domain));
 
@@ -961,8 +960,7 @@ int sh_unsync(struct vcpu *v, mfn_t gmfn)
 
     ASSERT(paging_locked_by_me(v->domain));
 
-    SHADOW_PRINTK("d=%d, v=%d, gmfn=%05lx\n",
-                  v->domain->domain_id, v->vcpu_id, mfn_x(gmfn));
+    SHADOW_PRINTK("%pv gmfn=%"PRI_mfn"\n", v, mfn_x(gmfn));
 
     pg = mfn_to_page(gmfn);
 
@@ -2792,7 +2790,7 @@ void sh_remove_shadows(struct domain *d, mfn_t gmfn, int fast, int all)
      * can be called via put_page_type when we clear a shadow l1e).*/
     paging_lock_recursive(d);
 
-    SHADOW_PRINTK("d=%d: gmfn=%lx\n", d->domain_id, mfn_x(gmfn));
+    SHADOW_PRINTK("d%d gmfn=%"PRI_mfn"\n", d->domain_id, mfn_x(gmfn));
 
     /* Bail out now if the page is not shadowed */
     if ( (pg->count_info & PGC_page_table) == 0 )
@@ -2847,7 +2845,7 @@ void sh_remove_shadows(struct domain *d, mfn_t gmfn, int fast, int all)
     /* If that didn't catch the shadows, something is wrong */
     if ( !fast && all && (pg->count_info & PGC_page_table) )
     {
-        SHADOW_ERROR("can't find all shadows of mfn %05lx "
+        SHADOW_ERROR("can't find all shadows of mfn %"PRI_mfn" "
                      "(shadow_flags=%08x)\n",
                       mfn_x(gmfn), pg->shadow_flags);
         domain_crash(d);
@@ -3016,9 +3014,9 @@ static void sh_update_paging_modes(struct vcpu *v)
 
         if ( v->arch.paging.mode != old_mode )
         {
-            SHADOW_PRINTK("new paging mode: d=%u v=%u pe=%d gl=%u "
+            SHADOW_PRINTK("new paging mode: %pv pe=%d gl=%u "
                           "sl=%u (was g=%u s=%u)\n",
-                          d->domain_id, v->vcpu_id,
+                          v,
                           is_hvm_domain(d) ? hvm_paging_enabled(v) : 1,
                           v->arch.paging.mode->guest_levels,
                           v->arch.paging.mode->shadow.shadow_levels,
@@ -3033,11 +3031,10 @@ static void sh_update_paging_modes(struct vcpu *v)
 
                 if ( v != current && vcpu_runnable(v) )
                 {
-                    SHADOW_ERROR("Some third party (d=%u v=%u) is changing "
-                                 "this HVM vcpu's (d=%u v=%u) paging mode "
+                    SHADOW_ERROR("Some third party (%pv) is changing "
+                                 "this HVM vcpu's (%pv) paging mode "
                                  "while it is running.\n",
-                                 current->domain->domain_id, current->vcpu_id,
-                                 v->domain->domain_id, v->vcpu_id);
+                                 current, v);
                     /* It's not safe to do that because we can't change
                      * the host CR3 for a running domain */
                     domain_crash(v->domain);
diff --git a/xen/arch/x86/mm/shadow/multi.c b/xen/arch/x86/mm/shadow/multi.c
index 833f279..6c45338 100644
--- a/xen/arch/x86/mm/shadow/multi.c
+++ b/xen/arch/x86/mm/shadow/multi.c
@@ -116,7 +116,7 @@ static inline void
 set_fl1_shadow_status(struct domain *d, gfn_t gfn, mfn_t smfn)
 /* Put an FL1 shadow into the hash table */
 {
-    SHADOW_PRINTK("gfn=%"SH_PRI_gfn", type=%08x, smfn=%05lx\n",
+    SHADOW_PRINTK("gfn=%"SH_PRI_gfn", type=%08x, smfn=%"PRI_mfn"\n",
                    gfn_x(gfn), SH_type_fl1_shadow, mfn_x(smfn));
 
     ASSERT(mfn_to_page(smfn)->u.sh.head);
@@ -129,7 +129,7 @@ set_shadow_status(struct domain *d, mfn_t gmfn, u32 shadow_type, mfn_t smfn)
 {
     int res;
 
-    SHADOW_PRINTK("d=%d: gmfn=%lx, type=%08x, smfn=%lx\n",
+    SHADOW_PRINTK("d%d gmfn=%lx, type=%08x, smfn=%lx\n",
                   d->domain_id, mfn_x(gmfn), shadow_type, mfn_x(smfn));
 
     ASSERT(mfn_to_page(smfn)->u.sh.head);
@@ -148,7 +148,7 @@ static inline void
 delete_fl1_shadow_status(struct domain *d, gfn_t gfn, mfn_t smfn)
 /* Remove a shadow from the hash table */
 {
-    SHADOW_PRINTK("gfn=%"SH_PRI_gfn", type=%08x, smfn=%05lx\n",
+    SHADOW_PRINTK("gfn=%"SH_PRI_gfn", type=%08x, smfn=%"PRI_mfn"\n",
                    gfn_x(gfn), SH_type_fl1_shadow, mfn_x(smfn));
     ASSERT(mfn_to_page(smfn)->u.sh.head);
     shadow_hash_delete(d, gfn_x(gfn), SH_type_fl1_shadow, smfn);
@@ -158,7 +158,7 @@ static inline void
 delete_shadow_status(struct domain *d, mfn_t gmfn, u32 shadow_type, mfn_t smfn)
 /* Remove a shadow from the hash table */
 {
-    SHADOW_PRINTK("d=%d: gmfn=%lx, type=%08x, smfn=%lx\n",
+    SHADOW_PRINTK("d%d gmfn=%"PRI_mfn", type=%08x, smfn=%"PRI_mfn"\n",
                   d->domain_id, mfn_x(gmfn), shadow_type, mfn_x(smfn));
     ASSERT(mfn_to_page(smfn)->u.sh.head);
     shadow_hash_delete(d, mfn_x(gmfn), shadow_type, smfn);
@@ -865,8 +865,8 @@ shadow_get_page_from_l1e(shadow_l1e_t sl1e, struct domain *d, p2m_type_t type)
         res = xsm_priv_mapping(XSM_TARGET, d, owner);
         if ( !res ) {
             res = get_page_from_l1e(sl1e, d, owner);
-            SHADOW_PRINTK("privileged domain %d installs map of mfn %05lx "
-                           "which is owned by domain %d: %s\n",
+            SHADOW_PRINTK("privileged domain %d installs map of mfn %"PRI_mfn" "
+                           "which is owned by d%d: %s\n",
                            d->domain_id, mfn_x(mfn), owner->domain_id,
                            res >= 0 ? "success" : "failed");
         }
@@ -1530,7 +1530,7 @@ sh_make_shadow(struct vcpu *v, mfn_t gmfn, u32 shadow_type)
 {
     struct domain *d = v->domain;
     mfn_t smfn = shadow_alloc(d, shadow_type, mfn_x(gmfn));
-    SHADOW_DEBUG(MAKE_SHADOW, "(%05lx, %u)=>%05lx\n",
+    SHADOW_DEBUG(MAKE_SHADOW, "(%"PRI_mfn", %u)=>%"PRI_mfn"\n",
                   mfn_x(gmfn), shadow_type, mfn_x(smfn));
 
     if ( sh_type_has_up_pointer(d, shadow_type) )
@@ -1918,8 +1918,7 @@ void sh_destroy_l4_shadow(struct domain *d, mfn_t smfn)
     u32 t = sp->u.sh.type;
     mfn_t gmfn, sl4mfn;
 
-    SHADOW_DEBUG(DESTROY_SHADOW,
-                  "%s(%05lx)\n", __func__, mfn_x(smfn));
+    SHADOW_DEBUG(DESTROY_SHADOW, "%"PRI_mfn"\n", mfn_x(smfn));
     ASSERT(t == SH_type_l4_shadow);
     ASSERT(sp->u.sh.head);
 
@@ -1949,8 +1948,7 @@ void sh_destroy_l3_shadow(struct domain *d, mfn_t smfn)
     u32 t = sp->u.sh.type;
     mfn_t gmfn, sl3mfn;
 
-    SHADOW_DEBUG(DESTROY_SHADOW,
-                  "%s(%05lx)\n", __func__, mfn_x(smfn));
+    SHADOW_DEBUG(DESTROY_SHADOW, "%"PRI_mfn"\n", mfn_x(smfn));
     ASSERT(t == SH_type_l3_shadow);
     ASSERT(sp->u.sh.head);
 
@@ -1981,8 +1979,7 @@ void sh_destroy_l2_shadow(struct domain *d, mfn_t smfn)
     u32 t = sp->u.sh.type;
     mfn_t gmfn, sl2mfn;
 
-    SHADOW_DEBUG(DESTROY_SHADOW,
-                  "%s(%05lx)\n", __func__, mfn_x(smfn));
+    SHADOW_DEBUG(DESTROY_SHADOW, "%"PRI_mfn"\n", mfn_x(smfn));
 
 #if GUEST_PAGING_LEVELS >= 3
     ASSERT(t == SH_type_l2_shadow || t == SH_type_l2h_shadow);
@@ -2015,8 +2012,7 @@ void sh_destroy_l1_shadow(struct domain *d, mfn_t smfn)
     struct page_info *sp = mfn_to_page(smfn);
     u32 t = sp->u.sh.type;
 
-    SHADOW_DEBUG(DESTROY_SHADOW,
-                  "%s(%05lx)\n", __func__, mfn_x(smfn));
+    SHADOW_DEBUG(DESTROY_SHADOW, "%"PRI_mfn"\n", mfn_x(smfn));
     ASSERT(t == SH_type_l1_shadow || t == SH_type_fl1_shadow);
     ASSERT(sp->u.sh.head);
 
@@ -2192,9 +2188,9 @@ static int validate_gl4e(struct vcpu *v, void *new_ge, mfn_t sl4mfn, void *se)
         {
             // attempt by the guest to write to a xen reserved slot
             //
-            SHADOW_PRINTK("%s out-of-range update "
-                           "sl4mfn=%05lx index=%#x val=%" SH_PRI_pte "\n",
-                           __func__, mfn_x(sl4mfn), shadow_index, new_sl4e.l4);
+            SHADOW_PRINTK("out-of-range update "
+                          "sl4mfn=%"PRI_mfn" index=%#x val=%" SH_PRI_pte "\n",
+                          mfn_x(sl4mfn), shadow_index, new_sl4e.l4);
             if ( shadow_l4e_get_flags(new_sl4e) & _PAGE_PRESENT )
             {
                 SHADOW_ERROR("out-of-range l4e update\n");
@@ -2877,9 +2873,8 @@ static int sh_page_fault(struct vcpu *v,
     int fast_emul = 0;
 #endif
 
-    SHADOW_PRINTK("d:v=%u:%u va=%#lx err=%u, rip=%lx\n",
-                  v->domain->domain_id, v->vcpu_id, va, regs->error_code,
-                  regs->eip);
+    SHADOW_PRINTK("%pv va=%#lx err=%#x, rip=%lx\n",
+                  v, va, regs->error_code, regs->eip);
 
     perfc_incr(shadow_fault);
 
@@ -3995,9 +3990,8 @@ sh_update_cr3(struct vcpu *v, int do_locking)
     }
 #endif
 
-    SHADOW_PRINTK("d=%u v=%u guest_table=%05lx\n",
-                   d->domain_id, v->vcpu_id,
-                   (unsigned long)pagetable_get_pfn(v->arch.guest_table));
+    SHADOW_PRINTK("%pv guest_table=%"PRI_mfn"\n",
+                  v, (unsigned long)pagetable_get_pfn(v->arch.guest_table));
 
 #if GUEST_PAGING_LEVELS == 4
     if ( !(v->arch.flags & TF_kernel_mode) && !is_pv_32bit_domain(d) )
-- 
2.1.4


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel

[PATCH 2/2] xen/trace: Turn the stub debugtrace_{dump, printk}() macros into functions

[Andrew Cooper]

This allows printf format checking to be performed, and for
debugtrace_printk() to evaluate its arguments, even if debugtrace is disabled
at compile time.

No intended change.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
---
CC: Jan Beulich <JBeulich@suse.com>
CC: Tim Deegan <tim@xen.org>
CC: George Dunlap <george.dunlap@eu.citrix.com>
---
 xen/include/xen/lib.h | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/xen/include/xen/lib.h b/xen/include/xen/lib.h
index d04864e..0008d63 100644
--- a/xen/include/xen/lib.h
+++ b/xen/include/xen/lib.h
@@ -68,8 +68,10 @@ extern void debugtrace_dump(void);
 extern void debugtrace_printk(const char *fmt, ...)
     __attribute__ ((format (printf, 1, 2)));
 #else
-#define debugtrace_dump()          ((void)0)
-#define debugtrace_printk(_f, ...) ((void)0)
+static inline void debugtrace_dump(void) {};
+static inline void
+ __attribute__ ((format (printf, 1, 2)))
+debugtrace_printk(const char *fmt, ...) {};
 #endif
 
 /* Allows us to use '%p' as general-purpose machine-word format char. */
-- 
2.1.4


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel

Re: [PATCH 2/2] xen/trace: Turn the stub debugtrace_{dump, printk}() macros into functions

[Jan Beulich]

>>> On 01.09.16 at 21:21, <andrew.cooper3@citrix.com> wrote:
> --- a/xen/include/xen/lib.h
> +++ b/xen/include/xen/lib.h
> @@ -68,8 +68,10 @@ extern void debugtrace_dump(void);
>  extern void debugtrace_printk(const char *fmt, ...)
>      __attribute__ ((format (printf, 1, 2)));
>  #else
> -#define debugtrace_dump()          ((void)0)
> -#define debugtrace_printk(_f, ...) ((void)0)
> +static inline void debugtrace_dump(void) {};
> +static inline void
> + __attribute__ ((format (printf, 1, 2)))
> +debugtrace_printk(const char *fmt, ...) {};
>  #endif

With the stray semicolons dropped, and provided this (at least a
little surprisingly) doesn't cause any other fallout with
DEBUG_TRACE_DUMP defined,
Acked-by: Jan Beulich <jbeulich@suse.com>

Jan




_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel

Re: [PATCH 2/2] xen/trace: Turn the stub debugtrace_{dump, printk}() macros into functions

[Andrew Cooper]

On 02/09/16 08:57, Jan Beulich wrote:
>>>> On 01.09.16 at 21:21, <andrew.cooper3@citrix.com> wrote:
>> --- a/xen/include/xen/lib.h
>> +++ b/xen/include/xen/lib.h
>> @@ -68,8 +68,10 @@ extern void debugtrace_dump(void);
>>  extern void debugtrace_printk(const char *fmt, ...)
>>      __attribute__ ((format (printf, 1, 2)));
>>  #else
>> -#define debugtrace_dump()          ((void)0)
>> -#define debugtrace_printk(_f, ...) ((void)0)
>> +static inline void debugtrace_dump(void) {};
>> +static inline void
>> + __attribute__ ((format (printf, 1, 2)))
>> +debugtrace_printk(const char *fmt, ...) {};
>>  #endif
> With the stray semicolons dropped

Oh yes of course.

> and provided this (at least a little surprisingly) doesn't cause any other fallout with
> DEBUG_TRACE_DUMP defined,

I don't know what you mean by this.  We strictly only change the
non-defined case, and that compiles fine on all architectures.

~Andrew

> Acked-by: Jan Beulich <jbeulich@suse.com>
>
> Jan
>
>
>


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel

Re: [PATCH 2/2] xen/trace: Turn the stub debugtrace_{dump, printk}() macros into functions

[Jan Beulich]

>>> On 02.09.16 at 12:00, <andrew.cooper3@citrix.com> wrote:
> On 02/09/16 08:57, Jan Beulich wrote:
>>>>> On 01.09.16 at 21:21, <andrew.cooper3@citrix.com> wrote:
>>> --- a/xen/include/xen/lib.h
>>> +++ b/xen/include/xen/lib.h
>>> @@ -68,8 +68,10 @@ extern void debugtrace_dump(void);
>>>  extern void debugtrace_printk(const char *fmt, ...)
>>>      __attribute__ ((format (printf, 1, 2)));
>>>  #else
>>> -#define debugtrace_dump()          ((void)0)
>>> -#define debugtrace_printk(_f, ...) ((void)0)
>>> +static inline void debugtrace_dump(void) {};
>>> +static inline void
>>> + __attribute__ ((format (printf, 1, 2)))
>>> +debugtrace_printk(const char *fmt, ...) {};
>>>  #endif
>> With the stray semicolons dropped
> 
> Oh yes of course.
> 
>> and provided this (at least a little surprisingly) doesn't cause any other fallout with
>> DEBUG_TRACE_DUMP defined,
> 
> I don't know what you mean by this.  We strictly only change the
> non-defined case,

Oh, sorry.

> and that compiles fine on all architectures.

Good.

Jan


_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel

Re: [PATCH 1/2] x86/shadow: More consistent printing for debug messages

[Tim Deegan]

At 20:21 +0100 on 01 Sep (1472761306), Andrew Cooper wrote:
>  * Use %pv or just d%d in preference to the multiple current ways of
>    presenting the same information.
>  * Use PRI_mfn instead of opencoding it.
>  * Drop all explicit use of __func__ from SHADOW_{PRINTK,DEBUG}() calls.  The
>    wrappers already include it.
>  * Use hex rather than decimal for printing a pagefault error code.
> 
> Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>

Acked-by: Tim Deegan <tim@xen.org>

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel