Re: [PATCH 03/15] xen/tools: tracing: several improvements on IRQs tracing

From: "Jan Beulich" <JBeulich@suse.com>
To: Dario Faggioli <dario.faggioli@citrix.com>
Cc: George Dunlap <george.dunlap@eu.citrix.com>,
	Andrew Cooper <andrew.cooper3@citrix.com>,
	Wei Liu <wei.liu2@citrix.com>,
	Ian Jackson <ian.jackson@eu.citrix.com>,
	xen-devel@lists.xenproject.org
Subject: Re: [PATCH 03/15] xen/tools: tracing: several improvements on IRQs tracing
Date: Wed, 07 Jun 2017 09:05:01 -0600	[thread overview]
Message-ID: <5938323D02000078001607B7@prv-mh.provo.novell.com> (raw)
In-Reply-To: <149633843555.12814.16573412358602741145.stgit@Solace.fritz.box>

>>> On 01.06.17 at 19:33, <dario.faggioli@citrix.com> wrote:
> More specifically:
>  - the handling of the TRC_HW_IRQ_HANDLED is fixed, both in
>    xentrace_format and in xenalyze;
>  - simple events for recording when we enter and exit the
>    do_IRQ function, as well as when we deal with a guest
>    IRQ, are added;

On x86. What about ARM?

>  - tracing of IRQs handled with direct vectors is also
>    added.
> 
> With all the above, a trace will now look like this (using
> xenalyze):
> 
>  0.001299072 .x- d32768v5 irq_enter, irq 80000000
>  0.001299072 .x- d32768v5 irq_direct, vec fa, handler = 0xffff82d08026d7e4
>  0.001300014 .x- d32768v5 raise_softirq nr 0
>  0.001300487 .x- d32768v5 irq_exit irq 80000000, in_irq = 0

The IRQ number looks bogus here, and I'm not convinced giving
a bogus example in a commit message is a good idea. I realize
this is presumably a result of vector_irq[] being initialized to
INT_MIN, but I would say the trace points would then better be
moved so that no bogus data is being recorded.

> @@ -884,9 +919,13 @@ void do_IRQ(struct cpu_user_regs *regs)
>              desc->rl_quantum_start = now;
>          }
>  
> -        tsc_in = tb_init_done ? get_cycles() : 0;
> +        if ( unlikely(tb_init_done) )
> +        {
> +            __trace_var(TRC_HW_IRQ_GUEST, 0, sizeof(irq), &irq);
> +            tsc_in = get_cycles();
> +        }
>          __do_IRQ_guest(irq);
> -        TRACE_3D(TRC_HW_IRQ_HANDLED, irq, tsc_in, get_cycles());
> +        trace_irq_handled(irq, get_cycles() - tsc_in);
>          goto out_no_end;
>      }

Before this change, the get_cycles() invocation was after
the tb_init_done check. Now you move it ahead of it (as
the function arguments are evaluated before executing the
function body) - are you sure all compiler versions will suitably
re-order this?

Additionally I'm afraid this will trigger compiler warnings on at
least some compiler versions, as tsc_in is now possibly
uninitialized (and there's no clear way to disprove this for the
compiler, again because function arguments are being
evaluated before the function body is reached).

As to get_cycles() itself - is the relatively imprecise time
stamp it produces really good enough for tracing? I notice
that there are only very few other users of that function.

> @@ -922,6 +962,7 @@ void do_IRQ(struct cpu_user_regs *regs)
>      spin_unlock(&desc->lock);
>   out_no_unlock:
>      irq_exit();
> +    TRACE_3D(TRC_HW_IRQ_EXIT, irq, desc == NULL ? -1 : desc->status, in_irq());

The ordering of irq_{enter,exit}() and TRACE_{1,3}D() may be
preferable from a trace quality pov, but as far as the system is
concerned you're adding code which runs in interrupt context
without being aware of that. This may be a latent issue.

Jan

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