| Message ID | 148838001098.11900.3627376252047944752.stgit@Solace.fritz.box (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
On 01/03/17 14:53, Dario Faggioli wrote: > 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> That looks good, thanks: Acked-by: George Dunlap <george.dunlap@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(+) > > diff --git a/tools/xentrace/formats b/tools/xentrace/formats > index 72c0b24..a055231 100644 > --- a/tools/xentrace/formats > +++ b/tools/xentrace/formats > @@ -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 ] > diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c > index 2678e2a..68ffcc2 100644 > --- a/tools/xentrace/xenalyze.c > +++ b/tools/xentrace/xenalyze.c > @@ -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: > diff --git a/xen/common/schedule.c b/xen/common/schedule.c > index 36bbd94..223a120 100644 > --- a/xen/common/schedule.c > +++ b/xen/common/schedule.c > @@ -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); > } > diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h > index 5ef9c37..7f2e891 100644 > --- a/xen/include/public/trace.h > +++ b/xen/include/public/trace.h > @@ -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) >
diff --git a/tools/xentrace/formats b/tools/xentrace/formats index 72c0b24..a055231 100644 --- a/tools/xentrace/formats +++ b/tools/xentrace/formats @@ -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 ] diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c index 2678e2a..68ffcc2 100644 --- a/tools/xentrace/xenalyze.c +++ b/tools/xentrace/xenalyze.c @@ -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: diff --git a/xen/common/schedule.c b/xen/common/schedule.c index 36bbd94..223a120 100644 --- a/xen/common/schedule.c +++ b/xen/common/schedule.c @@ -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); } diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h index 5ef9c37..7f2e891 100644 --- a/xen/include/public/trace.h +++ b/xen/include/public/trace.h @@ -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(+)