xen/tools: tracing: improve tracing of context switches.

Right now, two out of the three events related to
context switch (that is TRC_SCHED_SWITCH_INFPREV and
TRC_SCHED_SWITCH_INFNEXT) only report the domain id,
and not the vcpu id.

That's omitting a useful piece of information, and
even if we be figured that out by looking at other
records, that's unnecessarily complicated (especially
if working on a trace from a sctipt).

This changes both the tracing code in Xen and the parsing
code in tools at once, to avoid introducing transitional
regressions.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
Acked-by: George Dunlap <george.dunlap@citrix.com>

tools/xentrace/formats

@@ -32,8 +32,8 @@
 0x0002800b  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  s_timer_fn
 0x0002800c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  t_timer_fn
 0x0002800d  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  dom_timer_fn
-0x0002800e  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infprev    [ old_domid = 0x%(1)08x, runtime = %(2)d ]
-0x0002800f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infnext    [ new_domid = 0x%(1)08x, time = %(2)d, r_time = %(3)d ]
+0x0002800e  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infprev    [ dom:vcpu = 0x%(1)04x%(2)04x, runtime = %(3)d ]
+0x0002800f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infnext    [ new_dom:vcpu = 0x%(1)04x%(2)04x, time = %(3)d, r_time = %(4)d ]
 0x00028010  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown_code [ dom:vcpu = 0x%(1)04x%(2)04x, reason = 0x%(3)08x ]
 
 0x00022001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:sched_tasklet

tools/xentrace/xenalyze.c

@@ -7501,28 +7501,29 @@ void sched_process(struct pcpu_info *p)
         case TRC_SCHED_SWITCH_INFPREV:
             if(opt.dump_all) {
                 struct {
-                    unsigned int domid, runtime;
+                    unsigned int domid, vcpuid, runtime;
                 } *r = (typeof(r))ri->d;
 
-                printf(" %s sched_switch prev d%u, run for %u.%uus\n",
-                       ri->dump_header, r->domid, r->runtime / 1000,
-                       r->runtime % 1000);
+                printf(" %s sched_switch prev d%uv%d, run for %u.%uus\n",
+                       ri->dump_header, r->domid, r->vcpuid,
+                       r->runtime / 1000, r->runtime % 1000);
             }
             break;
         case TRC_SCHED_SWITCH_INFNEXT:
             if(opt.dump_all)
             {
                 struct {
-                    unsigned int domid, rsince;
+                    unsigned int domid, vcpuid, rsince;
                     int slice;
                 } *r = (typeof(r))ri->d;
 
-                printf(" %s sched_switch next d%u", ri->dump_header, r->domid);
+                printf(" %s sched_switch next d%uv%u", ri->dump_header,
+                       r->domid, r->vcpuid);
                 if ( r->rsince != 0 )
-                    printf(", was runnable for %u.%uus, ", r->rsince / 1000,
+                    printf(", was runnable for %u.%uus", r->rsince / 1000,
                            r->rsince % 1000);
                 if ( r->slice > 0 )
-                    printf("next slice %u.%uus", r->slice / 1000,
+                    printf(", next slice %u.%uus", r->slice / 1000,
                            r->slice % 1000);
                 printf("\n");
             }

xen/common/schedule.c

@@ -1388,11 +1388,11 @@ static void schedule(void)
         return continue_running(prev);
     }
 
-    TRACE_2D(TRC_SCHED_SWITCH_INFPREV,
-             prev->domain->domain_id,
+    TRACE_3D(TRC_SCHED_SWITCH_INFPREV,
+             prev->domain->domain_id, prev->vcpu_id,
              now - prev->runstate.state_entry_time);
-    TRACE_3D(TRC_SCHED_SWITCH_INFNEXT,
-             next->domain->domain_id,
+    TRACE_4D(TRC_SCHED_SWITCH_INFNEXT,
+             next->domain->domain_id, next->vcpu_id,
              (next->runstate.state == RUNSTATE_runnable) ?
              (now - next->runstate.state_entry_time) : 0,
              next_slice.time);