Re: [Xen-devel] [PATCH v4 7/7] xen/tools: tracing: Report next slice time when continuing as well as switching

[George Dunlap <george.dunlap@xxxxxxxxxx>]

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@xxxxxxxxxx>

That looks good, thanks:

Acked-by: George Dunlap <george.dunlap@xxxxxxxxxx>

> ---
> Cc: George Dunlap <george.dunlap@xxxxxxxxxxxxx>
> ---
> 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)
> 


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