diff mbox

[v2] qemu-log: add log category for MMU info

Message ID 1412938761-24283-1-git-send-email-antonynpavlov@gmail.com
State New
Headers show

Commit Message

Antony Pavlov Oct. 10, 2014, 10:59 a.m. UTC 
Running barebox on qemu-system-mips* with '-d unimp' overloads
stderr by very very many mips_cpu_handle_mmu_fault() messages:

  mips_cpu_handle_mmu_fault address=b80003fd ret 0 physical 00000000180003fd prot 3
  mips_cpu_handle_mmu_fault address=a0800884 ret 0 physical 0000000000800884 prot 3
  mips_cpu_handle_mmu_fault pc a080cd80 ad b80003fd rw 0 mmu_idx 0

So it's very difficult to find LOG_UNIMP message.

The mips_cpu_handle_mmu_fault() messages appears on enabling ANY
logging! It's not very handy.

Adding separate log category for *_cpu_handle_mmu_fault()
logging fixes the problem.

Signed-off-by: Antony Pavlov <antonynpavlov@gmail.com>
---

Changes since v1:

 * add cris, i386, microblaze, ppc, s390x, sparc and unicore32 support.

---

 cputlb.c                   |  3 ++-
 include/qemu/log.h         |  1 +
 qemu-log.c                 |  2 ++
 target-cris/helper.c       | 12 +++++++-----
 target-i386/helper.c       | 18 +++++++++---------
 target-microblaze/helper.c | 15 +++++++++++----
 target-mips/helper.c       |  6 ++++--
 target-ppc/mmu-hash32.c    |  2 +-
 target-s390x/helper.c      |  4 ++--
 target-sparc/mmu_helper.c  | 14 ++++++++++----
 target-unicore32/softmmu.c |  3 ++-
 11 files changed, 51 insertions(+), 29 deletions(-)

Comments

Peter Maydell Oct. 10, 2014, 2:47 p.m. UTC | #1 
On 10 October 2014 11:59, Antony Pavlov <antonynpavlov@gmail.com> wrote:
> Running barebox on qemu-system-mips* with '-d unimp' overloads
> stderr by very very many mips_cpu_handle_mmu_fault() messages:
>
>   mips_cpu_handle_mmu_fault address=b80003fd ret 0 physical 00000000180003fd prot 3
>   mips_cpu_handle_mmu_fault address=a0800884 ret 0 physical 0000000000800884 prot 3
>   mips_cpu_handle_mmu_fault pc a080cd80 ad b80003fd rw 0 mmu_idx 0
>
> So it's very difficult to find LOG_UNIMP message.
>
> The mips_cpu_handle_mmu_fault() messages appears on enabling ANY
> logging! It's not very handy.
>
> Adding separate log category for *_cpu_handle_mmu_fault()
> logging fixes the problem.
>
> Signed-off-by: Antony Pavlov <antonynpavlov@gmail.com>

This mostly looks good, thanks!

I should also note that I'm happy for us to just implement
the common-code (ie the log flag) and fix those targets
which are particularly obnoxious about logging and/or
easy to fix. We can always leave the other targets to
update their code later (or you could update other targets
in separate patches once the main one has gone in).

A minor tweak:

> --- a/target-cris/helper.c
> +++ b/target-cris/helper.c
> @@ -30,9 +30,11 @@
>  #ifdef CRIS_HELPER_DEBUG
>  #define D(x) x
>  #define D_LOG(...) qemu_log(__VA_ARGS__)
> +#define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
>  #else
>  #define D(x)
>  #define D_LOG(...) do { } while (0)
> +#define LOG_MMU(...) do { } while (0)
>  #endif

Now this logging is configurably enablable at runtime,
we should just call qemu_log_mask() directly, rather
than wrapping it in a LOG_MMU macro which might be compiled
out.

> --- a/target-i386/helper.c
> +++ b/target-i386/helper.c
> @@ -27,6 +27,12 @@
>
>  //#define DEBUG_MMU
>
> +#ifdef DEBUG_MMU
> +#  define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
> +#else
> +#  define LOG_MMU(...) do { } while (0)
> +#endif

Similarly here.

> --- a/target-microblaze/helper.c
> +++ b/target-microblaze/helper.c
> @@ -22,7 +22,14 @@
>  #include "qemu/host-utils.h"
>
>  #define D(x)
> -#define DMMU(x)
> +
> +#undef DEBUG_MMU
> +
> +#ifdef DEBUG_MMU
> +#  define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
> +#else
> +#  define LOG_MMU(...) do { } while (0)
> +#endif

and here.

> --- a/target-ppc/mmu-hash32.c
> +++ b/target-ppc/mmu-hash32.c

There are other PPC files which also do MMU logging;
we should either fix them all or none of them.

thanks
-- PMM
Alexander Graf Oct. 13, 2014, 2:50 p.m. UTC | #2 
On 10.10.14 16:47, Peter Maydell wrote:
> On 10 October 2014 11:59, Antony Pavlov <antonynpavlov@gmail.com> wrote:
>> Running barebox on qemu-system-mips* with '-d unimp' overloads
>> stderr by very very many mips_cpu_handle_mmu_fault() messages:
>>
>>   mips_cpu_handle_mmu_fault address=b80003fd ret 0 physical 00000000180003fd prot 3
>>   mips_cpu_handle_mmu_fault address=a0800884 ret 0 physical 0000000000800884 prot 3
>>   mips_cpu_handle_mmu_fault pc a080cd80 ad b80003fd rw 0 mmu_idx 0
>>
>> So it's very difficult to find LOG_UNIMP message.
>>
>> The mips_cpu_handle_mmu_fault() messages appears on enabling ANY
>> logging! It's not very handy.
>>
>> Adding separate log category for *_cpu_handle_mmu_fault()
>> logging fixes the problem.
>>
>> Signed-off-by: Antony Pavlov <antonynpavlov@gmail.com>
> 
> This mostly looks good, thanks!
> 
> I should also note that I'm happy for us to just implement
> the common-code (ie the log flag) and fix those targets
> which are particularly obnoxious about logging and/or
> easy to fix. We can always leave the other targets to
> update their code later (or you could update other targets
> in separate patches once the main one has gone in).
> 
> A minor tweak:
> 
>> --- a/target-cris/helper.c
>> +++ b/target-cris/helper.c
>> @@ -30,9 +30,11 @@
>>  #ifdef CRIS_HELPER_DEBUG
>>  #define D(x) x
>>  #define D_LOG(...) qemu_log(__VA_ARGS__)
>> +#define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
>>  #else
>>  #define D(x)
>>  #define D_LOG(...) do { } while (0)
>> +#define LOG_MMU(...) do { } while (0)
>>  #endif
> 
> Now this logging is configurably enablable at runtime,
> we should just call qemu_log_mask() directly, rather
> than wrapping it in a LOG_MMU macro which might be compiled
> out.

The MMU lookups are in a pretty hot path. Are you sure we always want to
have the log enabled checks and register pollution in there?


Alex
diff mbox

Patch

diff --git a/cputlb.c b/cputlb.c
index a55518a..3b271d4 100644
--- a/cputlb.c
+++ b/cputlb.c
@@ -270,7 +270,8 @@  void tlb_set_page(CPUState *cpu, target_ulong vaddr,
     assert(sz >= TARGET_PAGE_SIZE);
 
 #if defined(DEBUG_TLB)
-    printf("tlb_set_page: vaddr=" TARGET_FMT_lx " paddr=0x" TARGET_FMT_plx
+    qemu_log_mask(CPU_LOG_MMU,
+           "tlb_set_page: vaddr=" TARGET_FMT_lx " paddr=0x" TARGET_FMT_plx
            " prot=%x idx=%d\n",
            vaddr, paddr, prot, mmu_idx);
 #endif
diff --git a/include/qemu/log.h b/include/qemu/log.h
index d515424..195f665 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -40,6 +40,7 @@  static inline bool qemu_log_enabled(void)
 #define CPU_LOG_RESET      (1 << 9)
 #define LOG_UNIMP          (1 << 10)
 #define LOG_GUEST_ERROR    (1 << 11)
+#define CPU_LOG_MMU        (1 << 12)
 
 /* Returns true if a bit is set in the current loglevel mask
  */
diff --git a/qemu-log.c b/qemu-log.c
index 797f2af..05b5493 100644
--- a/qemu-log.c
+++ b/qemu-log.c
@@ -106,6 +106,8 @@  const QEMULogItem qemu_log_items[] = {
       "show trace before each executed TB (lots of logs)" },
     { CPU_LOG_TB_CPU, "cpu",
       "show CPU state before block translation" },
+    { CPU_LOG_MMU, "mmu",
+      "log MMU-related activities" },
     { CPU_LOG_PCALL, "pcall",
       "x86 only: show protected mode far calls/returns/exceptions" },
     { CPU_LOG_RESET, "cpu_reset",
diff --git a/target-cris/helper.c b/target-cris/helper.c
index e901c3a..e368e23 100644
--- a/target-cris/helper.c
+++ b/target-cris/helper.c
@@ -30,9 +30,11 @@ 
 #ifdef CRIS_HELPER_DEBUG
 #define D(x) x
 #define D_LOG(...) qemu_log(__VA_ARGS__)
+#define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
 #else
 #define D(x)
 #define D_LOG(...) do { } while (0)
+#define LOG_MMU(...) do { } while (0)
 #endif
 
 #if defined(CONFIG_USER_ONLY)
@@ -84,8 +86,8 @@  int cris_cpu_handle_mmu_fault(CPUState *cs, vaddr address, int rw,
     int r = -1;
     target_ulong phy;
 
-    D(printf("%s addr=%" VADDR_PRIx " pc=%x rw=%x\n",
-             __func__, address, env->pc, rw));
+    LOG_MMU("%s addr=%" VADDR_PRIx " pc=%x rw=%x\n",
+            __func__, address, env->pc, rw);
     miss = cris_mmu_translate(&res, env, address & TARGET_PAGE_MASK,
                               rw, mmu_idx, 0);
     if (miss) {
@@ -112,9 +114,9 @@  int cris_cpu_handle_mmu_fault(CPUState *cs, vaddr address, int rw,
         r = 0;
     }
     if (r > 0) {
-        D_LOG("%s returns %d irqreq=%x addr=%" VADDR_PRIx " phy=%x vec=%x"
-              " pc=%x\n", __func__, r, cs->interrupt_request, address, res.phy,
-              res.bf_vec, env->pc);
+        LOG_MMU("%s returns %d irqreq=%x addr=%" VADDR_PRIx " phy=%x vec=%x"
+                " pc=%x\n", __func__, r, cs->interrupt_request, address,
+                res.phy, res.bf_vec, env->pc);
     }
     return r;
 }
diff --git a/target-i386/helper.c b/target-i386/helper.c
index 345bda1..ae159a3 100644
--- a/target-i386/helper.c
+++ b/target-i386/helper.c
@@ -27,6 +27,12 @@ 
 
 //#define DEBUG_MMU
 
+#ifdef DEBUG_MMU
+#  define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
+#else
+#  define LOG_MMU(...) do { } while (0)
+#endif
+
 static void cpu_x86_version(CPUX86State *env, int *family, int *model)
 {
     int cpuver = env->cpuid_version;
@@ -388,9 +394,7 @@  void x86_cpu_set_a20(X86CPU *cpu, int a20_state)
     if (a20_state != ((env->a20_mask >> 20) & 1)) {
         CPUState *cs = CPU(cpu);
 
-#if defined(DEBUG_MMU)
-        printf("A20 update: a20=%d\n", a20_state);
-#endif
+        LOG_MMU("A20 update: a20=%d\n", a20_state);
         /* if the cpu is currently executing code, we must unlink it and
            all the potentially executing TB */
         cpu_interrupt(cs, CPU_INTERRUPT_EXITTB);
@@ -407,9 +411,7 @@  void cpu_x86_update_cr0(CPUX86State *env, uint32_t new_cr0)
     X86CPU *cpu = x86_env_get_cpu(env);
     int pe_state;
 
-#if defined(DEBUG_MMU)
-    printf("CR0 update: CR0=0x%08x\n", new_cr0);
-#endif
+    LOG_MMU("CR0 update: CR0=0x%08x\n", new_cr0);
     if ((new_cr0 & (CR0_PG_MASK | CR0_WP_MASK | CR0_PE_MASK)) !=
         (env->cr[0] & (CR0_PG_MASK | CR0_WP_MASK | CR0_PE_MASK))) {
         tlb_flush(CPU(cpu), 1);
@@ -452,9 +454,7 @@  void cpu_x86_update_cr3(CPUX86State *env, target_ulong new_cr3)
 
     env->cr[3] = new_cr3;
     if (env->cr[0] & CR0_PG_MASK) {
-#if defined(DEBUG_MMU)
-        printf("CR3 update: CR3=" TARGET_FMT_lx "\n", new_cr3);
-#endif
+        LOG_MMU("CR3 update: CR3=" TARGET_FMT_lx "\n", new_cr3);
         tlb_flush(CPU(cpu), 0);
     }
 }
diff --git a/target-microblaze/helper.c b/target-microblaze/helper.c
index 59466c9..7b48d17 100644
--- a/target-microblaze/helper.c
+++ b/target-microblaze/helper.c
@@ -22,7 +22,14 @@ 
 #include "qemu/host-utils.h"
 
 #define D(x)
-#define DMMU(x)
+
+#undef DEBUG_MMU
+
+#ifdef DEBUG_MMU
+#  define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
+#else
+#  define LOG_MMU(...) do { } while (0)
+#endif
 
 #if defined(CONFIG_USER_ONLY)
 
@@ -75,13 +82,13 @@  int mb_cpu_handle_mmu_fault(CPUState *cs, vaddr address, int rw,
             vaddr = address & TARGET_PAGE_MASK;
             paddr = lu.paddr + vaddr - lu.vaddr;
 
-            DMMU(qemu_log("MMU map mmu=%d v=%x p=%x prot=%x\n",
-                     mmu_idx, vaddr, paddr, lu.prot));
+            LOG_MMU("MMU map mmu=%d v=%x p=%x prot=%x\n",
+                    mmu_idx, vaddr, paddr, lu.prot);
             tlb_set_page(cs, vaddr, paddr, lu.prot, mmu_idx, TARGET_PAGE_SIZE);
             r = 0;
         } else {
             env->sregs[SR_EAR] = address;
-            DMMU(qemu_log("mmu=%d miss v=%x\n", mmu_idx, address));
+            LOG_MMU("mmu=%d miss v=%x\n", mmu_idx, address);
 
             switch (lu.err) {
                 case ERR_PROT:
diff --git a/target-mips/helper.c b/target-mips/helper.c
index fe16820..127f52a 100644
--- a/target-mips/helper.c
+++ b/target-mips/helper.c
@@ -309,7 +309,8 @@  int mips_cpu_handle_mmu_fault(CPUState *cs, vaddr address, int rw,
 #if 0
     log_cpu_state(cs, 0);
 #endif
-    qemu_log("%s pc " TARGET_FMT_lx " ad %" VADDR_PRIx " rw %d mmu_idx %d\n",
+    qemu_log_mask(CPU_LOG_MMU,
+              "%s pc " TARGET_FMT_lx " ad %" VADDR_PRIx " rw %d mmu_idx %d\n",
               __func__, env->active_tc.PC, address, rw, mmu_idx);
 
     rw &= 1;
@@ -321,7 +322,8 @@  int mips_cpu_handle_mmu_fault(CPUState *cs, vaddr address, int rw,
     access_type = ACCESS_INT;
     ret = get_physical_address(env, &physical, &prot,
                                address, rw, access_type);
-    qemu_log("%s address=%" VADDR_PRIx " ret %d physical " TARGET_FMT_plx
+    qemu_log_mask(CPU_LOG_MMU,
+             "%s address=%" VADDR_PRIx " ret %d physical " TARGET_FMT_plx
              " prot %d\n",
              __func__, address, ret, physical, prot);
     if (ret == TLBRET_MATCH) {
diff --git a/target-ppc/mmu-hash32.c b/target-ppc/mmu-hash32.c
index 0a13a81..0737d72 100644
--- a/target-ppc/mmu-hash32.c
+++ b/target-ppc/mmu-hash32.c
@@ -28,7 +28,7 @@ 
 //#define DEBUG_BAT
 
 #ifdef DEBUG_MMU
-#  define LOG_MMU(...) qemu_log(__VA_ARGS__)
+#  define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
 #  define LOG_MMU_STATE(cpu) log_cpu_state((cpu), 0)
 #else
 #  define LOG_MMU(...) do { } while (0)
diff --git a/target-s390x/helper.c b/target-s390x/helper.c
index e21afe6..96c7590 100644
--- a/target-s390x/helper.c
+++ b/target-s390x/helper.c
@@ -461,8 +461,8 @@  int s390_cpu_handle_mmu_fault(CPUState *cs, vaddr orig_vaddr,
         return 1;
     }
 
-    DPRINTF("%s: set tlb %" PRIx64 " -> %" PRIx64 " (%x)\n", __func__,
-            (uint64_t)vaddr, (uint64_t)raddr, prot);
+    qemu_log_mask(CPU_LOG_MMU, "%s: set tlb %" PRIx64 " -> %" PRIx64 " (%x)\n",
+            __func__, (uint64_t)vaddr, (uint64_t)raddr, prot);
 
     tlb_set_page(cs, orig_vaddr, raddr, prot,
                  mmu_idx, TARGET_PAGE_SIZE);
diff --git a/target-sparc/mmu_helper.c b/target-sparc/mmu_helper.c
index 61afbcf..cfd9a4e 100644
--- a/target-sparc/mmu_helper.c
+++ b/target-sparc/mmu_helper.c
@@ -23,6 +23,14 @@ 
 
 /* Sparc MMU emulation */
 
+#undef DEBUG_MMU
+
+#ifdef DEBUG_MMU
+#  define LOG_MMU(...) qemu_log_mask(CPU_LOG_MMU, __VA_ARGS__)
+#else
+#  define LOG_MMU(...) do { } while (0)
+#endif
+
 #if defined(CONFIG_USER_ONLY)
 
 int sparc_cpu_handle_mmu_fault(CPUState *cs, vaddr address, int rw,
@@ -213,10 +221,8 @@  int sparc_cpu_handle_mmu_fault(CPUState *cs, vaddr address, int rw,
                                       address, rw, mmu_idx, &page_size);
     vaddr = address;
     if (error_code == 0) {
-#ifdef DEBUG_MMU
-        printf("Translate at %" VADDR_PRIx " -> " TARGET_FMT_plx ", vaddr "
-               TARGET_FMT_lx "\n", address, paddr, vaddr);
-#endif
+        LOG_MMU("Translate at %" VADDR_PRIx " -> " TARGET_FMT_plx ", vaddr "
+                TARGET_FMT_lx "\n", address, paddr, vaddr);
         tlb_set_page(cs, vaddr, paddr, prot, mmu_idx, page_size);
         return 0;
     }
diff --git a/target-unicore32/softmmu.c b/target-unicore32/softmmu.c
index 9a3786d..42be555 100644
--- a/target-unicore32/softmmu.c
+++ b/target-unicore32/softmmu.c
@@ -236,7 +236,8 @@  int uc32_cpu_handle_mmu_fault(CPUState *cs, vaddr address,
             ret = get_phys_addr_ucv2(env, address, access_type, is_user,
                                     &phys_addr, &prot, &page_size);
             if (is_user) {
-                DPRINTF("user space access: ret %x, address %" VADDR_PRIx ", "
+                qemu_log_mask(CPU_LOG_MMU,
+                        "user space access: ret %x, address %" VADDR_PRIx ", "
                         "access_type %x, phys_addr %x, prot %x\n",
                         ret, address, access_type, phys_addr, prot);
             }