@@ -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:
@@ -1398,6 +1398,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)
In fact, it is quite useful a pice of information, to know how long it is the "next time slice" a vCPU has been granted. It allows one to assume (and then check) when the scheduler is supposed to run next, and other things. While this information is indeed reported when a context switch happens, it is not when the same vCPU that is running, continues to run. Fix that, with the following outcome. Before this change: 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 ????????????? That is, in the second block, it is shown that d1v5 was already running and will continue to do so, but we have no idea for how long. OTOH, after the change: 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> --- 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(+)