Re: [PATCH v2 06/16] xen: sched: tracing: enable TSC tracing for all events

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

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

On Thu, 2016-02-18 at 11:43 +0000, George Dunlap wrote:
> On 17/02/16 09:52, Dario Faggioli wrote:
> > 
> > For instance, the thing that you can just change on the fly the way
> > a
> > trace is shown (by tweaking the format file) looks an interesting
> > feature to me, even considering all the limitations of "pure"
> > xentrace.
> > And if one want to change the formats for her own purposes, I feel
> > like
> > it is important that the one that we ship is updated, and can be
> > used
> > as a decent base for that.
> 
> So I certainly agree that xentrace_formats should be maintained so
> that
> it works.  I hadn't thought before about the advantage of being able
> to
> change the formats file more easily than adding new records to
> xenalyze,
> but that's a good point.
> 
Yeah... To be fair, it's much more the exception than the rule, IMO,
that you really need xentrace_format instead of xenalyze... But it can
happen, and that's one possible reason.

> But I do want to ask, how neccessary / useful is it to make the *TSC*
> information available to xentrace_format?
> 
So, when tracing the scheduler, I personally don't see much value in
having the record of an event, if I don't also have the time at which
the event happened.

So, this is an example of xentrace_format with all this series applied,
except for this patch:

CPU0  2970034498098 (+ 9454788)  domain_wake       [ dom:vcpu = 0x00000001 ]
CPU0  2970034499304 (+    1206)  blocked_to_runnable [ dom:vcpu = 0x00000001 ]
CPU0  0 (+       0)  csched:tickle        [ cpu = 0 ]
CPU0  2970034511640 (+   12336)  switch_infprev    [ old_domid = 0x00007fff, runtime = 3956318 ]
CPU0  2970034512090 (+     450)  switch_infnext    [ new_domid = 0x00000000, time = 4446, r_time = 30000000 ]
CPU0  2970034512480 (+     390)  __enter_scheduler [ prev<dom:vcpu> = 0x7fff0000, next<dom:vcpu> = 0x00000001 ]
CPU0  2970034513002 (+     522)  running_to_runnable [ dom:vcpu = 0x7fff0000 ]
CPU0  2970034513422 (+     420)  runnable_to_running [ dom:vcpu = 0x00000001 ]

So, suppose, for instance, I want to figure out how much time passes
between when a pcpu is tickled, and when it actually schedules and pick
up the task that woke up. From just the trace above, I can't do that.

I know that this may not always be reliable when using only
xentrace_format (because of TSC not being synchronized or drifting),
but if used well (e.g., with pinning) or on good/new enough hardware
(with synch and constant rate TSCs), I think it should be possible.

On the other hand this is how a similar trace looks if TSC is enabled,
where the above can be achived:

CPU5  9965509909596 (+ 9268404)  domain_wake       [ dom:vcpu = 0x00000004 ]
CPU5  9965509911030 (+    1434)  blocked_to_runnable [ dom:vcpu = 0x00000004 ]
CPU5  9965509912962 (+    1932)  csched:tickle        [ cpu = 5 ]
CPU5  9965509924002 (+   11040)  switch_infprev    [ old_domid = 0x00007fff, runtime = 3879052 ]
CPU5  9965509924506 (+     504)  switch_infnext    [ new_domid = 0x00000000, time = 5000, r_time = 30000000 ]
CPU5  9965509924824 (+     318)  __enter_scheduler [ prev<dom:vcpu> = 0x7fff0005, next<dom:vcpu> = 0x00000004 ]
CPU5  9965509925478 (+     654)  running_to_runnable [ dom:vcpu = 0x7fff0005 ]
CPU5  9965509925892 (+     414)  runnable_to_running [ dom:vcpu = 0x00000004 ]

This is not an issue with xenalyze, and I think that is because you
fiddle with timestamps in it, in order to compensate for the per-
cpuness/desynch/etc. issues. I haven't checked the code where that
happens in xenalyze, though, so I don't know whether having the TSC in
more records would also help xenalyze or not.

> The reason most of the traces don't include a timestamp is that it
> increases the record size by a non-negligible amount -- in all the
> cases
> here the traces are 1, 2, or 3 bytes without the tsc, so you're
> basically doubling the size of what gets traced.
> 
I see, but I think it's worth in this case.

Perhaps, we can think of ways of enabling and disabling logging TSC
dynamically, either at compile or run time. Doing at run time, given
the way tracing is currently implemented, will most likely incur in
some overhead. Very small, but still something, and I'm not sure we're
ok introducing it.

Doing it at compile time would be a lot less flexible, but perhaps a
decent compromise, i.e., I at least always have the events... If I want
to know exactly when they happened, for all of them, I need a Xen
version build to provide that (like I need a debug build to have
ASSERT()s and symbols).

> How does adding the TSC significantly help someone using
> xentrace_format?
> 
Hope I answered to this. Let me know what you think. :-)

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: 181 bytes --]

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

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