@@ -35,6 +35,7 @@
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 ]
+0x00028011 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) switch_infcont [ dom:vcpu = 0x%(1)04x%(2)04x, runtime = %(3)d, r_time = %(4)d ]
0x00022001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:sched_tasklet
0x00022002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:account_start [ dom:vcpu = 0x%(1)04x%(2)04x, active = %(3)d ]
@@ -7528,6 +7528,23 @@ void sched_process(struct pcpu_info *p)
printf("\n");
}
break;
+ case TRC_SCHED_SWITCH_INFCONT:
+ if(opt.dump_all)
+ {
+ struct {
+ unsigned int domid, vcpuid, rsince;
+ int slice;
+ } *r = (typeof(r))ri->d;
+
+ printf(" %s sched_switch continue d%uv%u, run for %u.%uus",
+ ri->dump_header, r->domid, r->vcpuid,
+ r->rsince / 1000, r->rsince % 1000);
+ if ( r->slice > 0 )
+ printf(", next slice %u.%uus", r->slice / 1000,
+ r->slice % 1000);
+ printf("\n");
+ }
+ break;
case TRC_SCHED_CTL:
case TRC_SCHED_S_TIMER_FN:
case TRC_SCHED_T_TIMER_FN:
@@ -1397,6 +1397,10 @@ static void schedule(void)
if ( unlikely(prev == next) )
{
pcpu_schedule_unlock_irq(lock, cpu);
+ TRACE_4D(TRC_SCHED_SWITCH_INFCONT,
+ next->domain->domain_id, next->vcpu_id,
+ now - prev->runstate.state_entry_time,
+ next_slice.time);
trace_continue_running(next);
return continue_running(prev);
}
@@ -115,6 +115,7 @@
#define TRC_SCHED_SWITCH_INFPREV (TRC_SCHED_VERBOSE + 14)
#define TRC_SCHED_SWITCH_INFNEXT (TRC_SCHED_VERBOSE + 15)
#define TRC_SCHED_SHUTDOWN_CODE (TRC_SCHED_VERBOSE + 16)
+#define TRC_SCHED_SWITCH_INFCONT (TRC_SCHED_VERBOSE + 17)
#define TRC_DOM0_DOM_ADD (TRC_DOM0_DOMOPS + 1)
#define TRC_DOM0_DOM_REM (TRC_DOM0_DOMOPS + 2)
We record trace information about the next timeslice when switching to a different vcpu, but not when continuing to run the same cpu: csched2:schedule cpu 9, rq# 1, idle, SMT idle, tickled csched2:runq_candidate d0v3, 0 vcpus skipped, cpu 9 was tickled sched_switch prev d32767v9, run for 991.186us sched_switch next d0v3, was runnable for 2.515us, next slice 10000.0us sched_switch prev d32767v9 next d0v3 ^^^^^^^^^^^^^^^^^^^^ runstate_change d32767v9 running->runnable ... csched2:schedule cpu 2, rq# 0, busy, not tickled csched2:burn_credits d1v5, credit = 9996950, delta = 502913 csched2:runq_candidate d1v5, 0 vcpus skipped, no cpu was tickled runstate_continue d1v5 running->running ????????????? This information is quite useful; so add a trace including that information on the 'continue_running' path as well, like this: csched2:schedule cpu 1, rq# 0, busy, not tickled csched2:burn_credits d0v8, credit = 9998645, delta = 12104 csched2:runq_candidate d0v8, credit = 9998645, 0 vcpus skipped, no cpu was tickled sched_switch continue d0v8, run for 1125.820us, next slice 9998.645us runstate_continue d0v8 running->running ^^^^^^^^^^^^^^^^^^^^^ Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com> --- Cc: George Dunlap <george.dunlap@eu.citrix.com> --- Changes from v2: * reworded the changelog, as suggested during review. --- tools/xentrace/formats | 1 + tools/xentrace/xenalyze.c | 17 +++++++++++++++++ xen/common/schedule.c | 4 ++++ xen/include/public/trace.h | 1 + 4 files changed, 23 insertions(+)