Re: [Xen-devel] [PATCH v2 10/10] xen/tools: tracing: always report how long next slice will be.

[George Dunlap <George.Dunlap@xxxxxxxxxxxxx>]

On Thu, Feb 9, 2017 at 1:59 PM, Dario Faggioli
<dario.faggioli@xxxxxxxxxx> 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@xxxxxxxxxx>
> ---
> Cc: George Dunlap <george.dunlap@xxxxxxxxxxxxx>
> ---
>  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@xxxxxxxxxxxxx
> https://lists.xen.org/xen-devel

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
https://lists.xen.org/xen-devel