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

[Dario Faggioli <dario.faggioli@citrix.com>]

[-- Attachment #1.1: Type: text/plain, Size: 5014 bytes --]

On Wed, 2017-06-07 at 09:05 -0600, Jan Beulich wrote:
> > > > 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?
> 
We don't have tracing at all on ARM. I guess I can mention this in the
commit message (and, perhaps, even add an 'x86' tag to the subject).

> >  - 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.
> 
Ok, I'll have a look at how to achieve that.

> > @@ -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).
> 
I understand and (now that I see it) agree with your remark on when
get_cycles() is called. I'll reorganize things so that the patched
behavior matches the existing one.

OTOH, I'm not sure I see the "potentially uninitialized" issue for
tsc_in, but since I'm reworking the code, I'll keep that in mind too.

> 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.
> 
Yes, that's also something I was wondering. It's what is being used
currently, so I thought it was like that for a reason, and that it
wasn't this patch job to change that.

But if it's judged to be fine to turn this into NOW() (done either
here, or in a dedicated patch)., I'm all for it.

> > @@ -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.
> 
Sorry, I don't understand your concern(s). What is it that I am not
aware of, and what is it that could be a latent issue?

About the position of those tracepoints: the nice thing about IRQ_EXIT
following irq_exit() is that I can record the result of in_irq(), which
will tell whether or not we're dealing with a nested interrupt. I don't
 do the same for IRQ_ENTER, but, not that I think about it, I guess I
could.

However, if what you're saying is that they need to stay within the
irq_enter()-irq_exit() section, I can certainly make that happen. The
trace needs to be interpreted knowing where the tracepoints are anyway
(and that's true for each and every event already), so no big deal,
really.

Thanks and Regards,
Dario
-- 
<<This happens because I choose it to happen!>> (Raistlin Majere)
-----------------------------------------------------------------
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK)

[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 819 bytes --]

[-- Attachment #2: Type: text/plain, Size: 127 bytes --]

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