| Message ID | 148664876901.595.6987450024828384400.stgit@Solace.fritz.box (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
On Thu, Feb 9, 2017 at 1:59 PM, Dario Faggioli <dario.faggioli@citrix.com> wrote: > 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. The patch looks fine; but the description seems a bit round-about. I think I would have said something like: --- xen: Report next slice time when continuing as well as switching We record trace information about the next timeslice when switching to a different vcpu, but not when continuing to run the same cpu. This information is quite useful; so add a trace including that information on the 'continue_running' path as well. --- What do you think? -George > > 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(+) > > 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 e4320f3..495f138 100644 > --- a/xen/common/schedule.c > +++ b/xen/common/schedule.c > @@ -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); > } > 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) > > > _______________________________________________ > Xen-devel mailing list > Xen-devel@lists.xen.org > https://lists.xen.org/xen-devel
On Wed, 2017-02-15 at 15:40 +0000, George Dunlap wrote: > On Thu, Feb 9, 2017 at 1:59 PM, Dario Faggioli > <dario.faggioli@citrix.com> wrote: > xen: Report next slice time when continuing as well as switching > > We record trace information about the next timeslice when switching > to > a different vcpu, but not when continuing to run the same cpu. This > information > is quite useful; so add a trace including that information on the > 'continue_running' path as well. > > --- > > What do you think? > Ok, I like it. I did replace my changelog with your proposed one, but I've left the example output from xenalyze in place. Not sure whether you were suggesting to also kill that part. I do think it's useful so I left it there. But if you want it removed too, I can live with that, so just ask. :-) Thanks and Regards, Dario
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 e4320f3..495f138 100644 --- a/xen/common/schedule.c +++ b/xen/common/schedule.c @@ -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); } 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)
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(+)