Patchwork [RFC] Sparc: convert some debug printf statements to tracepoints

login
register
mail settings
Submitter Blue Swirl
Date Oct. 9, 2010, 3:10 p.m.
Message ID <AANLkTikNVu6FKXGC=uA3gT2X7LDi8W_gYX18K-iqNxT5@mail.gmail.com>
Download mbox | patch
Permalink /patch/67322/
State New
Headers show

Comments

Blue Swirl - Oct. 9, 2010, 3:10 p.m.
Replace some debug printf statements with tracepoints.

Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
---
I think tracing way is more flexible than current conditional code. I
remember wading through hundreds of megs of DPRINTF output looking for
a clue about a specific event, so being able to control the trace
dynamically is invaluable.

Here's example simpletrace.py output:
sparc64_translate 0.000 address=0x1fff0000040 paddr=0x1fff0000040
vaddr=0x1fff0000000 mmu_idx=0x4 primary_context=0x0
secondary_context=0x0
sparc64_translate 24.017 address=0x1fff000bc50 paddr=0x1fff000bc50
vaddr=0x1fff000a000 mmu_idx=0x4 primary_context=0x0
secondary_context=0x0
sparc64_translate 3.921 address=0x1fff000bc5c paddr=0x1fff000bc5c
vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
secondary_context=0x0
sparc64_translate 337.702 address=0x1fff000bf38 paddr=0x1fff000bf38
vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
secondary_context=0x0

There are problems #including "trace.h" from op_helper.c
(qemu-common.h conflicts with dyngen-exec.h), otherwise this looks
promising.
---
 target-sparc/helper.c |   65 +++++++++++-------------------------------------
 trace-events          |   10 +++++++
 2 files changed, 25 insertions(+), 50 deletions(-)

%" PRIx64 " context %" PRIx64
+disable sparc64_tfault(uint64_t address, uint64_t context) "TFAULT at
%" PRIx64 " context %" PRIx64
+disable sparc64_tmiss(uint64_t address, uint64_t context) "TMISS at
%" PRIx64 " context %" PRIx64
+disable sparc64_get_physical_address(const char *type, uint32_t tl,
int mmu_idx, uint64_t primary_context, uint64_t secondary_context,
uint64_t address) "%s tl=%d mmu_idx=%d primary context=%" PRIx64 "
secondary context=%" PRIx64 " address=%" PRIx64
+disable sparc64_translate(uint64_t address, uint64_t paddr, uint64_t
vaddr, int mmu_idx, uint64_t primary_context, uint64_t
secondary_context) "Translate at %" PRIx64 " -> %" PRIx64 ", vaddr %"
PRIx64 " mmu_idx=%d primary context=%" PRIx64 " secondary context=%"
PRIx64
+disable sparc32_translate(uint32_t address, uint64_t paddr, uint32_t
vaddr, int mmu_idx) "Translate at 0x%x -> %" PRIx64 ", vaddr 0x%x
mmu_idx=%d"
Andreas Färber - Oct. 9, 2010, 3:35 p.m.
Am 09.10.2010 um 17:10 schrieb Blue Swirl:

> Replace some debug printf statements with tracepoints.
>
> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
> ---
> I think tracing way is more flexible than current conditional code. I
> remember wading through hundreds of megs of DPRINTF output looking for
> a clue about a specific event, so being able to control the trace
> dynamically is invaluable.

While this may in theory be right, in practice the nop backend gives  
us nothing and the simple trace backend still has porting issues that  
need to be fixed.
I remember hacking around some time-related problems on Haiku (it was  
using an optional POSIX feature without check/wrapper), and there was  
a comment saying that similar changes need to be done for Win32  
support too.

Has anyone looked into a DTrace backend btw?

Andreas

> Here's example simpletrace.py output:
> sparc64_translate 0.000 address=0x1fff0000040 paddr=0x1fff0000040
> vaddr=0x1fff0000000 mmu_idx=0x4 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 24.017 address=0x1fff000bc50 paddr=0x1fff000bc50
> vaddr=0x1fff000a000 mmu_idx=0x4 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 3.921 address=0x1fff000bc5c paddr=0x1fff000bc5c
> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 337.702 address=0x1fff000bf38 paddr=0x1fff000bf38
> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
> secondary_context=0x0
>
> There are problems #including "trace.h" from op_helper.c
> (qemu-common.h conflicts with dyngen-exec.h), otherwise this looks
> promising.
> ---
> target-sparc/helper.c |   65 ++++++++++ 
> +-------------------------------------
> trace-events          |   10 +++++++
> 2 files changed, 25 insertions(+), 50 deletions(-)
>
> diff --git a/target-sparc/helper.c b/target-sparc/helper.c
> index aa1fd63..8078d92 100644
> --- a/target-sparc/helper.c
> +++ b/target-sparc/helper.c
> @@ -26,17 +26,11 @@
> #include "cpu.h"
> #include "exec-all.h"
> #include "qemu-common.h"
> +#include "trace.h"
>
> //#define DEBUG_MMU
> //#define DEBUG_FEATURES
>
> -#ifdef DEBUG_MMU
> -#define DPRINTF_MMU(fmt, ...) \
> -    do { printf("MMU: " fmt , ## __VA_ARGS__); } while (0)
> -#else
> -#define DPRINTF_MMU(fmt, ...) do {} while (0)
> -#endif
> -
> static int cpu_sparc_find_by_name(sparc_def_t *cpu_def, const char  
> *cpu_model);
>
> /* Sparc MMU emulation */
> @@ -240,10 +234,7 @@ int cpu_sparc_handle_mmu_fault (CPUState *env,
> target_ulong address, int rw,
>     if (error_code == 0) {
>         vaddr = address & TARGET_PAGE_MASK;
>         paddr &= TARGET_PAGE_MASK;
> -#ifdef DEBUG_MMU
> -        printf("Translate at " TARGET_FMT_lx " -> " TARGET_FMT_plx  
> ", vaddr "
> -               TARGET_FMT_lx "\n", address, paddr, vaddr);
> -#endif
> +        trace_sparc32_translate(address, paddr, vaddr, mmu_idx);
>         tlb_set_page(env, vaddr, paddr, prot, mmu_idx, page_size);
>         return 0;
>     }
> @@ -466,16 +457,10 @@ static int get_physical_address_data(CPUState  
> *env,
>             if ((env->dtlb[i].tte & 0x4) && is_user) {
>                 fault_type |= 1; /* privilege violation */
>                 env->exception_index = TT_DFAULT;
> -
> -                DPRINTF_MMU("DFAULT at %" PRIx64 " context %" PRIx64
> -                            " mmu_idx=%d tl=%d\n",
> -                            address, context, mmu_idx, env->tl);
> +                trace_sparc64_dfault(address, context, mmu_idx, env- 
> >tl);
>             } else if (!(env->dtlb[i].tte & 0x2) && (rw == 1)) {
>                 env->exception_index = TT_DPROT;
> -
> -                DPRINTF_MMU("DPROT at %" PRIx64 " context %" PRIx64
> -                            " mmu_idx=%d tl=%d\n",
> -                            address, context, mmu_idx, env->tl);
> +                trace_sparc64_dprot(address, context, mmu_idx, env- 
> >tl);
>             } else {
>                 *prot = PAGE_READ;
>                 if (env->dtlb[i].tte & 0x2)
> @@ -502,9 +487,7 @@ static int get_physical_address_data(CPUState  
> *env,
>         }
>     }
>
> -    DPRINTF_MMU("DMISS at %" PRIx64 " context %" PRIx64 "\n",
> -                address, context);
> -
> +    trace_sparc64_dmiss(address, context);
>     env->dmmu.tag_access = (address & ~0x1fffULL) | context;
>     env->exception_index = TT_DMISS;
>     return 1;
> @@ -549,9 +532,7 @@ static int get_physical_address_code(CPUState  
> *env,
>
>                 env->immu.tag_access = (address & ~0x1fffULL) |  
> context;
>
> -                DPRINTF_MMU("TFAULT at %" PRIx64 " context %"  
> PRIx64 "\n",
> -                            address, context);
> -
> +                trace_sparc64_tfault(address, context);
>                 return 1;
>             }
>             *prot = PAGE_EXEC;
> @@ -560,9 +541,7 @@ static int get_physical_address_code(CPUState  
> *env,
>         }
>     }
>
> -    DPRINTF_MMU("TMISS at %" PRIx64 " context %" PRIx64 "\n",
> -                address, context);
> -
> +    trace_sparc64_tmiss(address, context);
>     /* Context is stored in DMMU (dmmuregs[1]) also for IMMU */
>     env->immu.tag_access = (address & ~0x1fffULL) | context;
>     env->exception_index = TT_TMISS;
> @@ -578,21 +557,14 @@ static int get_physical_address(CPUState *env,
> target_phys_addr_t *physical,
>        everything when an entry is evicted.  */
>     *page_size = TARGET_PAGE_SIZE;
>
> -#if defined (DEBUG_MMU)
>     /* safety net to catch wrong softmmu index use from dynamic code  
> */
>     if (env->tl > 0 && mmu_idx != MMU_NUCLEUS_IDX) {
> -        DPRINTF_MMU("get_physical_address %s tl=%d mmu_idx=%d"
> -                    " primary context=%" PRIx64
> -                    " secondary context=%" PRIx64
> -                " address=%" PRIx64
> -                "\n",
> -                (rw == 2 ? "CODE" : "DATA"),
> -                env->tl, mmu_idx,
> -                env->dmmu.mmu_primary_context,
> -                env->dmmu.mmu_secondary_context,
> -                address);
> +        trace_sparc64_get_physical_address((rw == 2 ? "CODE" :  
> "DATA"),
> +                                           env->tl, mmu_idx,
> +                                           env- 
> >dmmu.mmu_primary_context,
> +                                           env- 
> >dmmu.mmu_secondary_context,
> +                                           address);
>     }
> -#endif
>
>     if (rw == 2)
>         return get_physical_address_code(env, physical, prot, address,
> @@ -618,16 +590,9 @@ int cpu_sparc_handle_mmu_fault (CPUState *env,
> target_ulong address, int rw,
>         vaddr = virt_addr + ((address & TARGET_PAGE_MASK) &
>                              (TARGET_PAGE_SIZE - 1));
>
> -        DPRINTF_MMU("Translate at %" PRIx64 " -> %" PRIx64 ","
> -                    " vaddr %" PRIx64
> -                    " mmu_idx=%d"
> -                    " tl=%d"
> -                    " primary context=%" PRIx64
> -                    " secondary context=%" PRIx64
> -                    "\n",
> -                    address, paddr, vaddr, mmu_idx, env->tl,
> -                    env->dmmu.mmu_primary_context,
> -                    env->dmmu.mmu_secondary_context);
> +        trace_sparc64_translate(address, paddr, vaddr, mmu_idx,
> +                                env->dmmu.mmu_primary_context,
> +                                env->dmmu.mmu_secondary_context);
>
>         tlb_set_page(env, vaddr, paddr, prot, mmu_idx, page_size);
>         return 0;
> diff --git a/trace-events b/trace-events
> index 4300178..da4c208 100644
> --- a/trace-events
> +++ b/trace-events
> @@ -69,3 +69,13 @@ disable cpu_out(unsigned int addr, unsigned int
> val) "addr %#x value %u"
> # balloon.c
> # Since requests are raised via monitor, not many tracepoints are  
> needed.
> disable balloon_event(void *opaque, unsigned long addr) "opaque %p  
> addr %lu"
> +
> +# target-sparc/helper.c
> +disable sparc64_dfault(uint64_t address, uint64_t context, int
> mmu_idx, uint32_t tl) "DFAULT at %" PRIx64 " context %" PRIx64
> "mmu_idx=%d tl=%d"
> +disable sparc64_dprot(uint64_t address, uint64_t context, int
> mmu_idx, uint32_t tl) "DFAULT at %" PRIx64 " context %" PRIx64
> "mmu_idx=%d tl=%d"
> +disable sparc64_dmiss(uint64_t address, uint64_t context) "DMISS at
> %" PRIx64 " context %" PRIx64
> +disable sparc64_tfault(uint64_t address, uint64_t context) "TFAULT at
> %" PRIx64 " context %" PRIx64
> +disable sparc64_tmiss(uint64_t address, uint64_t context) "TMISS at
> %" PRIx64 " context %" PRIx64
> +disable sparc64_get_physical_address(const char *type, uint32_t tl,
> int mmu_idx, uint64_t primary_context, uint64_t secondary_context,
> uint64_t address) "%s tl=%d mmu_idx=%d primary context=%" PRIx64 "
> secondary context=%" PRIx64 " address=%" PRIx64
> +disable sparc64_translate(uint64_t address, uint64_t paddr, uint64_t
> vaddr, int mmu_idx, uint64_t primary_context, uint64_t
> secondary_context) "Translate at %" PRIx64 " -> %" PRIx64 ", vaddr %"
> PRIx64 " mmu_idx=%d primary context=%" PRIx64 " secondary context=%"
> PRIx64
> +disable sparc32_translate(uint32_t address, uint64_t paddr, uint32_t
> vaddr, int mmu_idx) "Translate at 0x%x -> %" PRIx64 ", vaddr 0x%x
> mmu_idx=%d"
> -- 
> 1.6.2.4
>
Blue Swirl - Oct. 9, 2010, 3:46 p.m.
On Sat, Oct 9, 2010 at 3:35 PM, Andreas Färber <andreas.faerber@web.de> wrote:
> Am 09.10.2010 um 17:10 schrieb Blue Swirl:
>
>> Replace some debug printf statements with tracepoints.
>>
>> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
>> ---
>> I think tracing way is more flexible than current conditional code. I
>> remember wading through hundreds of megs of DPRINTF output looking for
>> a clue about a specific event, so being able to control the trace
>> dynamically is invaluable.
>
> While this may in theory be right, in practice the nop backend gives us
> nothing and the simple trace backend still has porting issues that need to
> be fixed.

Which issues, do you mean that Python isn't available for all platforms?

> I remember hacking around some time-related problems on Haiku (it was using
> an optional POSIX feature without check/wrapper), and there was a comment
> saying that similar changes need to be done for Win32 support too.
>
> Has anyone looked into a DTrace backend btw?

Is that more portable than the simple backend?
Andreas Färber - Oct. 9, 2010, 4 p.m.
Am 09.10.2010 um 17:46 schrieb Blue Swirl:

> On Sat, Oct 9, 2010 at 3:35 PM, Andreas Färber  
> <andreas.faerber@web.de> wrote:
>> Am 09.10.2010 um 17:10 schrieb Blue Swirl:
>>
>>> Replace some debug printf statements with tracepoints.
>>>
>>> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
>>> ---
>>> I think tracing way is more flexible than current conditional  
>>> code. I
>>> remember wading through hundreds of megs of DPRINTF output looking  
>>> for
>>> a clue about a specific event, so being able to control the trace
>>> dynamically is invaluable.
>>
>> While this may in theory be right, in practice the nop backend  
>> gives us
>> nothing and the simple trace backend still has porting issues that  
>> need to
>> be fixed.
>
> Which issues, do you mean that Python isn't available for all  
> platforms?

Python is installable on Win32, I'm talking about build failures, I'll  
check later.

>> I remember hacking around some time-related problems on Haiku (it  
>> was using
>> an optional POSIX feature without check/wrapper), and there was a  
>> comment
>> saying that similar changes need to be done for Win32 support too.
>>
>> Has anyone looked into a DTrace backend btw?
>
> Is that more portable than the simple backend?

No, but it's the native trace framework on Solaris and Mac OS X - two  
platforms where I have not yet checked whether the simple backend  
builds and works.
It's also been ported to FreeBSD, I think.

Andreas
Andreas Färber - Oct. 9, 2010, 6:33 p.m.
Am 09.10.2010 um 18:00 schrieb Andreas Färber:

> Am 09.10.2010 um 17:46 schrieb Blue Swirl:
>
>> On Sat, Oct 9, 2010 at 3:35 PM, Andreas Färber <andreas.faerber@web.de 
>> > wrote:
>>> Am 09.10.2010 um 17:10 schrieb Blue Swirl:
>>>
>>>> Replace some debug printf statements with tracepoints.
>>>>
>>>> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
>>>> ---
>>>> I think tracing way is more flexible than current conditional  
>>>> code. I
>>>> remember wading through hundreds of megs of DPRINTF output  
>>>> looking for
>>>> a clue about a specific event, so being able to control the trace
>>>> dynamically is invaluable.
>>>
>>> While this may in theory be right, in practice the nop backend  
>>> gives us
>>> nothing and the simple trace backend still has porting issues that  
>>> need to
>>> be fixed.
>>
>> Which issues, do you mean that Python isn't available for all  
>> platforms?
>
> Python is installable on Win32, I'm talking about build failures,  
> I'll check later.
>
>>> I remember hacking around some time-related problems on Haiku (it  
>>> was using
>>> an optional POSIX feature without check/wrapper), and there was a  
>>> comment
>>> saying that similar changes need to be done for Win32 support too.

On Mac OS X v10.5 I do get the same error as on Haiku:

   CC    simpletrace.o
/Users/andreas/QEMU/qemu/simpletrace.c: In function ‘trace’:
/Users/andreas/QEMU/qemu/simpletrace.c:149: warning: implicit  
declaration of function ‘clock_gettime’
/Users/andreas/QEMU/qemu/simpletrace.c:149: warning: nested extern  
declaration of ‘clock_gettime’
/Users/andreas/QEMU/qemu/simpletrace.c:149: error: ‘CLOCK_MONOTONIC’  
undeclared (first use in this function)
/Users/andreas/QEMU/qemu/simpletrace.c:149: error: (Each undeclared  
identifier is reported only once
/Users/andreas/QEMU/qemu/simpletrace.c:149: error: for each function  
it appears in.)
make: *** [simpletrace.o] Error 1

>>>> There are problems #including "trace.h" from op_helper.c
>>>> (qemu-common.h conflicts with dyngen-exec.h), otherwise this looks
>>>> promising.

According to the comment in simpletrace.c, it is caused by the same  
observation you made wrt header incompatibilities.
Maybe Stefan's dyngen cleanup patch helps with the header issue? Still  
need to test...

On Haiku I had used some BeOS time function instead at the time. The  
Haiku/ppc guest hangs qemu-system-ppc though and no {malloc,realloc}  
was traced (which it did via manual printf), so I'm unsure whether the  
log is just not being flushed or whether something else is not working.

Cheers,
Andreas
Blue Swirl - Oct. 9, 2010, 7:41 p.m.
On Sat, Oct 9, 2010 at 6:33 PM, Andreas Färber <andreas.faerber@web.de> wrote:
> Am 09.10.2010 um 18:00 schrieb Andreas Färber:
>
>> Am 09.10.2010 um 17:46 schrieb Blue Swirl:
>>
>>> On Sat, Oct 9, 2010 at 3:35 PM, Andreas Färber <andreas.faerber@web.de>
>>> wrote:
>>>>
>>>> Am 09.10.2010 um 17:10 schrieb Blue Swirl:
>>>>
>>>>> Replace some debug printf statements with tracepoints.
>>>>>
>>>>> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
>>>>> ---
>>>>> I think tracing way is more flexible than current conditional code. I
>>>>> remember wading through hundreds of megs of DPRINTF output looking for
>>>>> a clue about a specific event, so being able to control the trace
>>>>> dynamically is invaluable.
>>>>
>>>> While this may in theory be right, in practice the nop backend gives us
>>>> nothing and the simple trace backend still has porting issues that need
>>>> to
>>>> be fixed.
>>>
>>> Which issues, do you mean that Python isn't available for all platforms?
>>
>> Python is installable on Win32, I'm talking about build failures, I'll
>> check later.
>>
>>>> I remember hacking around some time-related problems on Haiku (it was
>>>> using
>>>> an optional POSIX feature without check/wrapper), and there was a
>>>> comment
>>>> saying that similar changes need to be done for Win32 support too.
>
> On Mac OS X v10.5 I do get the same error as on Haiku:
>
>  CC    simpletrace.o
> /Users/andreas/QEMU/qemu/simpletrace.c: In function ‘trace’:
> /Users/andreas/QEMU/qemu/simpletrace.c:149: warning: implicit declaration of
> function ‘clock_gettime’
> /Users/andreas/QEMU/qemu/simpletrace.c:149: warning: nested extern
> declaration of ‘clock_gettime’
> /Users/andreas/QEMU/qemu/simpletrace.c:149: error: ‘CLOCK_MONOTONIC’
> undeclared (first use in this function)
> /Users/andreas/QEMU/qemu/simpletrace.c:149: error: (Each undeclared
> identifier is reported only once
> /Users/andreas/QEMU/qemu/simpletrace.c:149: error: for each function it
> appears in.)
> make: *** [simpletrace.o] Error 1

Simpletrace should use qemu-timer, which should be made available to
tools etc. Alternatively, perhaps the real time difference is not so
interesting, so we could fake it with a counter if clocks are not
available.

>>>>> There are problems #including "trace.h" from op_helper.c
>>>>> (qemu-common.h conflicts with dyngen-exec.h), otherwise this looks
>>>>> promising.
>
> According to the comment in simpletrace.c, it is caused by the same
> observation you made wrt header incompatibilities.
> Maybe Stefan's dyngen cleanup patch helps with the header issue? Still need
> to test...
>
> On Haiku I had used some BeOS time function instead at the time. The
> Haiku/ppc guest hangs qemu-system-ppc though and no {malloc,realloc} was
> traced (which it did via manual printf), so I'm unsure whether the log is
> just not being flushed or whether something else is not working.

I also didn't get anything logged at first because trace.h contained
the nop versions (also I tried to enable an event by numeric ID, which
doesn't work, but there was also no error message). Maybe the Makefile
dependencies are not correct.
Artyom Tarasenko - Oct. 10, 2010, 5:37 p.m.
On Sat, Oct 9, 2010 at 5:10 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
> Replace some debug printf statements with tracepoints.
>
> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
> ---
> I think tracing way is more flexible than current conditional code. I
> remember wading through hundreds of megs of DPRINTF output looking for
> a clue about a specific event, so being able to control the trace
> dynamically is invaluable.
>
> Here's example simpletrace.py output:
> sparc64_translate 0.000 address=0x1fff0000040 paddr=0x1fff0000040
> vaddr=0x1fff0000000 mmu_idx=0x4 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 24.017 address=0x1fff000bc50 paddr=0x1fff000bc50
> vaddr=0x1fff000a000 mmu_idx=0x4 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 3.921 address=0x1fff000bc5c paddr=0x1fff000bc5c
> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 337.702 address=0x1fff000bf38 paddr=0x1fff000bf38
> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
> secondary_context=0x0
>
> There are problems #including "trace.h" from op_helper.c
> (qemu-common.h conflicts with dyngen-exec.h), otherwise this looks
> promising.
> ---
>  target-sparc/helper.c |   65 +++++++++++-------------------------------------
>  trace-events          |   10 +++++++
>  2 files changed, 25 insertions(+), 50 deletions(-)
>
> diff --git a/target-sparc/helper.c b/target-sparc/helper.c
> index aa1fd63..8078d92 100644
> --- a/target-sparc/helper.c
> +++ b/target-sparc/helper.c
> @@ -26,17 +26,11 @@
>  #include "cpu.h"
>  #include "exec-all.h"
>  #include "qemu-common.h"
> +#include "trace.h"
>
>  //#define DEBUG_MMU
>  //#define DEBUG_FEATURES
>
> -#ifdef DEBUG_MMU

wouldn't it be better to keep the #ifdefs? Don't mmu functions have a
strong impact on the performance?
Artyom Tarasenko - Oct. 10, 2010, 6:01 p.m.
On Sun, Oct 10, 2010 at 7:37 PM, Artyom Tarasenko <atar4qemu@gmail.com> wrote:
> On Sat, Oct 9, 2010 at 5:10 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
>> Replace some debug printf statements with tracepoints.
>>
>> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
>> ---
>> I think tracing way is more flexible than current conditional code. I
>> remember wading through hundreds of megs of DPRINTF output looking for
>> a clue about a specific event, so being able to control the trace
>> dynamically is invaluable.
>>
>> Here's example simpletrace.py output:
>> sparc64_translate 0.000 address=0x1fff0000040 paddr=0x1fff0000040
>> vaddr=0x1fff0000000 mmu_idx=0x4 primary_context=0x0
>> secondary_context=0x0
>> sparc64_translate 24.017 address=0x1fff000bc50 paddr=0x1fff000bc50
>> vaddr=0x1fff000a000 mmu_idx=0x4 primary_context=0x0
>> secondary_context=0x0
>> sparc64_translate 3.921 address=0x1fff000bc5c paddr=0x1fff000bc5c
>> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
>> secondary_context=0x0
>> sparc64_translate 337.702 address=0x1fff000bf38 paddr=0x1fff000bf38
>> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
>> secondary_context=0x0
>>
>> There are problems #including "trace.h" from op_helper.c
>> (qemu-common.h conflicts with dyngen-exec.h), otherwise this looks
>> promising.
>> ---
>>  target-sparc/helper.c |   65 +++++++++++-------------------------------------
>>  trace-events          |   10 +++++++
>>  2 files changed, 25 insertions(+), 50 deletions(-)
>>
>> diff --git a/target-sparc/helper.c b/target-sparc/helper.c
>> index aa1fd63..8078d92 100644
>> --- a/target-sparc/helper.c
>> +++ b/target-sparc/helper.c
>> @@ -26,17 +26,11 @@
>>  #include "cpu.h"
>>  #include "exec-all.h"
>>  #include "qemu-common.h"
>> +#include "trace.h"
>>
>>  //#define DEBUG_MMU
>>  //#define DEBUG_FEATURES
>>
>> -#ifdef DEBUG_MMU
>
> wouldn't it be better to keep the #ifdefs? Don't mmu functions have a
> strong impact on the performance?

After reading how the nop backed works, I take it back.
Blue Swirl - Oct. 10, 2010, 6:38 p.m.
On Sat, Oct 9, 2010 at 3:10 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
> Replace some debug printf statements with tracepoints.
>
> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
> ---
> I think tracing way is more flexible than current conditional code. I
> remember wading through hundreds of megs of DPRINTF output looking for
> a clue about a specific event, so being able to control the trace
> dynamically is invaluable.
>
> Here's example simpletrace.py output:
> sparc64_translate 0.000 address=0x1fff0000040 paddr=0x1fff0000040
> vaddr=0x1fff0000000 mmu_idx=0x4 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 24.017 address=0x1fff000bc50 paddr=0x1fff000bc50
> vaddr=0x1fff000a000 mmu_idx=0x4 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 3.921 address=0x1fff000bc5c paddr=0x1fff000bc5c
> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
> secondary_context=0x0
> sparc64_translate 337.702 address=0x1fff000bf38 paddr=0x1fff000bf38
> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
> secondary_context=0x0
>
> There are problems #including "trace.h" from op_helper.c
> (qemu-common.h conflicts with dyngen-exec.h), otherwise this looks
> promising.
> ---
>  target-sparc/helper.c |   65 +++++++++++-------------------------------------
>  trace-events          |   10 +++++++
>  2 files changed, 25 insertions(+), 50 deletions(-)
>
> diff --git a/target-sparc/helper.c b/target-sparc/helper.c
> index aa1fd63..8078d92 100644
> --- a/target-sparc/helper.c
> +++ b/target-sparc/helper.c
> @@ -26,17 +26,11 @@
>  #include "cpu.h"
>  #include "exec-all.h"
>  #include "qemu-common.h"
> +#include "trace.h"
>
>  //#define DEBUG_MMU
>  //#define DEBUG_FEATURES
>
> -#ifdef DEBUG_MMU
> -#define DPRINTF_MMU(fmt, ...) \
> -    do { printf("MMU: " fmt , ## __VA_ARGS__); } while (0)
> -#else
> -#define DPRINTF_MMU(fmt, ...) do {} while (0)
> -#endif
> -
>  static int cpu_sparc_find_by_name(sparc_def_t *cpu_def, const char *cpu_model);
>
>  /* Sparc MMU emulation */
> @@ -240,10 +234,7 @@ int cpu_sparc_handle_mmu_fault (CPUState *env,
> target_ulong address, int rw,
>     if (error_code == 0) {
>         vaddr = address & TARGET_PAGE_MASK;
>         paddr &= TARGET_PAGE_MASK;
> -#ifdef DEBUG_MMU
> -        printf("Translate at " TARGET_FMT_lx " -> " TARGET_FMT_plx ", vaddr "
> -               TARGET_FMT_lx "\n", address, paddr, vaddr);
> -#endif
> +        trace_sparc32_translate(address, paddr, vaddr, mmu_idx);
>         tlb_set_page(env, vaddr, paddr, prot, mmu_idx, page_size);
>         return 0;
>     }
> @@ -466,16 +457,10 @@ static int get_physical_address_data(CPUState *env,
>             if ((env->dtlb[i].tte & 0x4) && is_user) {
>                 fault_type |= 1; /* privilege violation */
>                 env->exception_index = TT_DFAULT;
> -
> -                DPRINTF_MMU("DFAULT at %" PRIx64 " context %" PRIx64
> -                            " mmu_idx=%d tl=%d\n",
> -                            address, context, mmu_idx, env->tl);
> +                trace_sparc64_dfault(address, context, mmu_idx, env->tl);
>             } else if (!(env->dtlb[i].tte & 0x2) && (rw == 1)) {
>                 env->exception_index = TT_DPROT;
> -
> -                DPRINTF_MMU("DPROT at %" PRIx64 " context %" PRIx64
> -                            " mmu_idx=%d tl=%d\n",
> -                            address, context, mmu_idx, env->tl);
> +                trace_sparc64_dprot(address, context, mmu_idx, env->tl);
>             } else {
>                 *prot = PAGE_READ;
>                 if (env->dtlb[i].tte & 0x2)
> @@ -502,9 +487,7 @@ static int get_physical_address_data(CPUState *env,
>         }
>     }
>
> -    DPRINTF_MMU("DMISS at %" PRIx64 " context %" PRIx64 "\n",
> -                address, context);
> -
> +    trace_sparc64_dmiss(address, context);
>     env->dmmu.tag_access = (address & ~0x1fffULL) | context;
>     env->exception_index = TT_DMISS;
>     return 1;
> @@ -549,9 +532,7 @@ static int get_physical_address_code(CPUState *env,
>
>                 env->immu.tag_access = (address & ~0x1fffULL) | context;
>
> -                DPRINTF_MMU("TFAULT at %" PRIx64 " context %" PRIx64 "\n",
> -                            address, context);
> -
> +                trace_sparc64_tfault(address, context);
>                 return 1;
>             }
>             *prot = PAGE_EXEC;
> @@ -560,9 +541,7 @@ static int get_physical_address_code(CPUState *env,
>         }
>     }
>
> -    DPRINTF_MMU("TMISS at %" PRIx64 " context %" PRIx64 "\n",
> -                address, context);
> -
> +    trace_sparc64_tmiss(address, context);
>     /* Context is stored in DMMU (dmmuregs[1]) also for IMMU */
>     env->immu.tag_access = (address & ~0x1fffULL) | context;
>     env->exception_index = TT_TMISS;
> @@ -578,21 +557,14 @@ static int get_physical_address(CPUState *env,
> target_phys_addr_t *physical,
>        everything when an entry is evicted.  */
>     *page_size = TARGET_PAGE_SIZE;
>
> -#if defined (DEBUG_MMU)
>     /* safety net to catch wrong softmmu index use from dynamic code */
>     if (env->tl > 0 && mmu_idx != MMU_NUCLEUS_IDX) {
> -        DPRINTF_MMU("get_physical_address %s tl=%d mmu_idx=%d"
> -                    " primary context=%" PRIx64
> -                    " secondary context=%" PRIx64
> -                " address=%" PRIx64
> -                "\n",
> -                (rw == 2 ? "CODE" : "DATA"),
> -                env->tl, mmu_idx,
> -                env->dmmu.mmu_primary_context,
> -                env->dmmu.mmu_secondary_context,
> -                address);
> +        trace_sparc64_get_physical_address((rw == 2 ? "CODE" : "DATA"),

Passing a pointer obviously won't work, the string will not be
accessible when processing the trace data.
Blue Swirl - Oct. 10, 2010, 6:47 p.m.
On Sun, Oct 10, 2010 at 6:01 PM, Artyom Tarasenko <atar4qemu@gmail.com> wrote:
> On Sun, Oct 10, 2010 at 7:37 PM, Artyom Tarasenko <atar4qemu@gmail.com> wrote:
>> On Sat, Oct 9, 2010 at 5:10 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
>>> Replace some debug printf statements with tracepoints.
>>>
>>> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
>>> ---
>>> I think tracing way is more flexible than current conditional code. I
>>> remember wading through hundreds of megs of DPRINTF output looking for
>>> a clue about a specific event, so being able to control the trace
>>> dynamically is invaluable.
>>>
>>> Here's example simpletrace.py output:
>>> sparc64_translate 0.000 address=0x1fff0000040 paddr=0x1fff0000040
>>> vaddr=0x1fff0000000 mmu_idx=0x4 primary_context=0x0
>>> secondary_context=0x0
>>> sparc64_translate 24.017 address=0x1fff000bc50 paddr=0x1fff000bc50
>>> vaddr=0x1fff000a000 mmu_idx=0x4 primary_context=0x0
>>> secondary_context=0x0
>>> sparc64_translate 3.921 address=0x1fff000bc5c paddr=0x1fff000bc5c
>>> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
>>> secondary_context=0x0
>>> sparc64_translate 337.702 address=0x1fff000bf38 paddr=0x1fff000bf38
>>> vaddr=0x1fff000a000 mmu_idx=0x2 primary_context=0x0
>>> secondary_context=0x0
>>>
>>> There are problems #including "trace.h" from op_helper.c
>>> (qemu-common.h conflicts with dyngen-exec.h), otherwise this looks
>>> promising.
>>> ---
>>>  target-sparc/helper.c |   65 +++++++++++-------------------------------------
>>>  trace-events          |   10 +++++++
>>>  2 files changed, 25 insertions(+), 50 deletions(-)
>>>
>>> diff --git a/target-sparc/helper.c b/target-sparc/helper.c
>>> index aa1fd63..8078d92 100644
>>> --- a/target-sparc/helper.c
>>> +++ b/target-sparc/helper.c
>>> @@ -26,17 +26,11 @@
>>>  #include "cpu.h"
>>>  #include "exec-all.h"
>>>  #include "qemu-common.h"
>>> +#include "trace.h"
>>>
>>>  //#define DEBUG_MMU
>>>  //#define DEBUG_FEATURES
>>>
>>> -#ifdef DEBUG_MMU
>>
>> wouldn't it be better to keep the #ifdefs? Don't mmu functions have a
>> strong impact on the performance?
>
> After reading how the nop backed works, I take it back.

Even a full trace with all Sparc stuff enabled using simpletrace
backend seems to have very low overhead compared to printfs. I suppose
async I/O would lower the overhead even more.
Stefan Hajnoczi - Oct. 11, 2010, 9:09 a.m.
On Sat, Oct 9, 2010 at 8:41 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
> On Sat, Oct 9, 2010 at 6:33 PM, Andreas Färber <andreas.faerber@web.de> wrote:
>> Am 09.10.2010 um 18:00 schrieb Andreas Färber:
>>
>>> Am 09.10.2010 um 17:46 schrieb Blue Swirl:
>>>
>>>> On Sat, Oct 9, 2010 at 3:35 PM, Andreas Färber <andreas.faerber@web.de>
>>>> wrote:
>>>>>
>>>>> Am 09.10.2010 um 17:10 schrieb Blue Swirl:
>>>>> I remember hacking around some time-related problems on Haiku (it was
>>>>> using
>>>>> an optional POSIX feature without check/wrapper), and there was a
>>>>> comment
>>>>> saying that similar changes need to be done for Win32 support too.
>>
>> On Mac OS X v10.5 I do get the same error as on Haiku:
>>
>>  CC    simpletrace.o
>> /Users/andreas/QEMU/qemu/simpletrace.c: In function ‘trace’:
>> /Users/andreas/QEMU/qemu/simpletrace.c:149: warning: implicit declaration of
>> function ‘clock_gettime’
>> /Users/andreas/QEMU/qemu/simpletrace.c:149: warning: nested extern
>> declaration of ‘clock_gettime’
>> /Users/andreas/QEMU/qemu/simpletrace.c:149: error: ‘CLOCK_MONOTONIC’
>> undeclared (first use in this function)
>> /Users/andreas/QEMU/qemu/simpletrace.c:149: error: (Each undeclared
>> identifier is reported only once
>> /Users/andreas/QEMU/qemu/simpletrace.c:149: error: for each function it
>> appears in.)
>> make: *** [simpletrace.o] Error 1
>
> Simpletrace should use qemu-timer, which should be made available to
> tools etc. Alternatively, perhaps the real time difference is not so
> interesting, so we could fake it with a counter if clocks are not
> available.

qemu-tool.c stubs out qemu_get_clock() for rt_clock.  This clock only
does millisecond precision whereas trace events should support the
highest precision available.

Keep in mind that common code used by simpletrace.c cannot be easily
traced (infinite recursion).

Still, I think fixing simpletrace clock would be worthwhile.

Stefan

Patch

diff --git a/target-sparc/helper.c b/target-sparc/helper.c
index aa1fd63..8078d92 100644
--- a/target-sparc/helper.c
+++ b/target-sparc/helper.c
@@ -26,17 +26,11 @@ 
 #include "cpu.h"
 #include "exec-all.h"
 #include "qemu-common.h"
+#include "trace.h"

 //#define DEBUG_MMU
 //#define DEBUG_FEATURES

-#ifdef DEBUG_MMU
-#define DPRINTF_MMU(fmt, ...) \
-    do { printf("MMU: " fmt , ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF_MMU(fmt, ...) do {} while (0)
-#endif
-
 static int cpu_sparc_find_by_name(sparc_def_t *cpu_def, const char *cpu_model);

 /* Sparc MMU emulation */
@@ -240,10 +234,7 @@  int cpu_sparc_handle_mmu_fault (CPUState *env,
target_ulong address, int rw,
     if (error_code == 0) {
         vaddr = address & TARGET_PAGE_MASK;
         paddr &= TARGET_PAGE_MASK;
-#ifdef DEBUG_MMU
-        printf("Translate at " TARGET_FMT_lx " -> " TARGET_FMT_plx ", vaddr "
-               TARGET_FMT_lx "\n", address, paddr, vaddr);
-#endif
+        trace_sparc32_translate(address, paddr, vaddr, mmu_idx);
         tlb_set_page(env, vaddr, paddr, prot, mmu_idx, page_size);
         return 0;
     }
@@ -466,16 +457,10 @@  static int get_physical_address_data(CPUState *env,
             if ((env->dtlb[i].tte & 0x4) && is_user) {
                 fault_type |= 1; /* privilege violation */
                 env->exception_index = TT_DFAULT;
-
-                DPRINTF_MMU("DFAULT at %" PRIx64 " context %" PRIx64
-                            " mmu_idx=%d tl=%d\n",
-                            address, context, mmu_idx, env->tl);
+                trace_sparc64_dfault(address, context, mmu_idx, env->tl);
             } else if (!(env->dtlb[i].tte & 0x2) && (rw == 1)) {
                 env->exception_index = TT_DPROT;
-
-                DPRINTF_MMU("DPROT at %" PRIx64 " context %" PRIx64
-                            " mmu_idx=%d tl=%d\n",
-                            address, context, mmu_idx, env->tl);
+                trace_sparc64_dprot(address, context, mmu_idx, env->tl);
             } else {
                 *prot = PAGE_READ;
                 if (env->dtlb[i].tte & 0x2)
@@ -502,9 +487,7 @@  static int get_physical_address_data(CPUState *env,
         }
     }

-    DPRINTF_MMU("DMISS at %" PRIx64 " context %" PRIx64 "\n",
-                address, context);
-
+    trace_sparc64_dmiss(address, context);
     env->dmmu.tag_access = (address & ~0x1fffULL) | context;
     env->exception_index = TT_DMISS;
     return 1;
@@ -549,9 +532,7 @@  static int get_physical_address_code(CPUState *env,

                 env->immu.tag_access = (address & ~0x1fffULL) | context;

-                DPRINTF_MMU("TFAULT at %" PRIx64 " context %" PRIx64 "\n",
-                            address, context);
-
+                trace_sparc64_tfault(address, context);
                 return 1;
             }
             *prot = PAGE_EXEC;
@@ -560,9 +541,7 @@  static int get_physical_address_code(CPUState *env,
         }
     }

-    DPRINTF_MMU("TMISS at %" PRIx64 " context %" PRIx64 "\n",
-                address, context);
-
+    trace_sparc64_tmiss(address, context);
     /* Context is stored in DMMU (dmmuregs[1]) also for IMMU */
     env->immu.tag_access = (address & ~0x1fffULL) | context;
     env->exception_index = TT_TMISS;
@@ -578,21 +557,14 @@  static int get_physical_address(CPUState *env,
target_phys_addr_t *physical,
        everything when an entry is evicted.  */
     *page_size = TARGET_PAGE_SIZE;

-#if defined (DEBUG_MMU)
     /* safety net to catch wrong softmmu index use from dynamic code */
     if (env->tl > 0 && mmu_idx != MMU_NUCLEUS_IDX) {
-        DPRINTF_MMU("get_physical_address %s tl=%d mmu_idx=%d"
-                    " primary context=%" PRIx64
-                    " secondary context=%" PRIx64
-                " address=%" PRIx64
-                "\n",
-                (rw == 2 ? "CODE" : "DATA"),
-                env->tl, mmu_idx,
-                env->dmmu.mmu_primary_context,
-                env->dmmu.mmu_secondary_context,
-                address);
+        trace_sparc64_get_physical_address((rw == 2 ? "CODE" : "DATA"),
+                                           env->tl, mmu_idx,
+                                           env->dmmu.mmu_primary_context,
+                                           env->dmmu.mmu_secondary_context,
+                                           address);
     }
-#endif

     if (rw == 2)
         return get_physical_address_code(env, physical, prot, address,
@@ -618,16 +590,9 @@  int cpu_sparc_handle_mmu_fault (CPUState *env,
target_ulong address, int rw,
         vaddr = virt_addr + ((address & TARGET_PAGE_MASK) &
                              (TARGET_PAGE_SIZE - 1));

-        DPRINTF_MMU("Translate at %" PRIx64 " -> %" PRIx64 ","
-                    " vaddr %" PRIx64
-                    " mmu_idx=%d"
-                    " tl=%d"
-                    " primary context=%" PRIx64
-                    " secondary context=%" PRIx64
-                    "\n",
-                    address, paddr, vaddr, mmu_idx, env->tl,
-                    env->dmmu.mmu_primary_context,
-                    env->dmmu.mmu_secondary_context);
+        trace_sparc64_translate(address, paddr, vaddr, mmu_idx,
+                                env->dmmu.mmu_primary_context,
+                                env->dmmu.mmu_secondary_context);

         tlb_set_page(env, vaddr, paddr, prot, mmu_idx, page_size);
         return 0;
diff --git a/trace-events b/trace-events
index 4300178..da4c208 100644
--- a/trace-events
+++ b/trace-events
@@ -69,3 +69,13 @@  disable cpu_out(unsigned int addr, unsigned int
val) "addr %#x value %u"
 # balloon.c
 # Since requests are raised via monitor, not many tracepoints are needed.
 disable balloon_event(void *opaque, unsigned long addr) "opaque %p addr %lu"
+
+# target-sparc/helper.c
+disable sparc64_dfault(uint64_t address, uint64_t context, int
mmu_idx, uint32_t tl) "DFAULT at %" PRIx64 " context %" PRIx64
"mmu_idx=%d tl=%d"
+disable sparc64_dprot(uint64_t address, uint64_t context, int
mmu_idx, uint32_t tl) "DFAULT at %" PRIx64 " context %" PRIx64
"mmu_idx=%d tl=%d"
+disable sparc64_dmiss(uint64_t address, uint64_t context) "DMISS at