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

[George Dunlap <dunlapg@xxxxxxxxx>]

On Thu, Feb 18, 2016 at 4:52 PM, Dario Faggioli
<dario.faggioli@xxxxxxxxxx> wrote:
> 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. :-)

The other thing to say in favor of this patch is: While we are
doubling the size of this small handful of traces, these will
constitute a much smaller percentage of the overall trace file,
particularly as (as you say in the changelog) a lot of the other
traces do already use tsc.

So I guess you've convinced me:

Acked-by: George Dunlap <george.dunlap@xxxxxxxxxx>

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