Re: [Xen-devel] [PATCH 09/24] xen/tools: tracing: improve tracing of context switches.

[George Dunlap <george.dunlap@xxxxxxxxxx>]

On 17/08/16 18:18, Dario Faggioli wrote:
> Right now, two out of the three events related to
> context switch (that is TRC_SCHED_SWITCH_INFPREV and
> TRC_SCHED_SWITCH_INFNEXT) only report the domain id,
> and not the vcpu id.
> 
> That's omitting a useful piece of information, and
> even if we be figured that out by looking at other
> records, that's unnecessarily complicated (especially
> if working on a trace from a sctipt).
> 
> This changes both the tracing code in Xen and the parsing
> code in tools at once, to avoid introducing transitional
> regressions.
> 
> Signed-off-by: Dario Faggioli <dario.faggioli@xxxxxxxxxx>

Hmm, I'm tempted to complain about the lack of packing; but in any case
I think these traces are redundant with the runstate change information,
so there's no need to be terribly picky. :-)

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

> ---
> Cc: George Dunlap <george.dunlap@xxxxxxxxxxxxx>
> Cc: Ian Jackson <ian.jackson@xxxxxxxxxxxxx>
> Cc: Wei Liu <wei.liu2@xxxxxxxxxx>
> ---
>  tools/xentrace/formats    |    4 ++--
>  tools/xentrace/xenalyze.c |   17 +++++++++--------
>  xen/common/schedule.c     |    8 ++++----
>  3 files changed, 15 insertions(+), 14 deletions(-)
> 
> diff --git a/tools/xentrace/formats b/tools/xentrace/formats
> index caafb5f..0de7990 100644
> --- a/tools/xentrace/formats
> +++ b/tools/xentrace/formats
> @@ -32,8 +32,8 @@
>  0x0002800b  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  s_timer_fn
>  0x0002800c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  t_timer_fn
>  0x0002800d  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  dom_timer_fn
> -0x0002800e  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infprev    [ 
> old_domid = 0x%(1)08x, runtime = %(2)d ]
> -0x0002800f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infnext    [ 
> new_domid = 0x%(1)08x, time = %(2)d, r_time = %(3)d ]
> +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 ]
>  
>  0x00022001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:sched_tasklet
> diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
> index 11763a8..0b697d0 100644
> --- a/tools/xentrace/xenalyze.c
> +++ b/tools/xentrace/xenalyze.c
> @@ -7501,28 +7501,29 @@ void sched_process(struct pcpu_info *p)
>          case TRC_SCHED_SWITCH_INFPREV:
>              if(opt.dump_all) {
>                  struct {
> -                    unsigned int domid, runtime;
> +                    unsigned int domid, vcpuid, runtime;
>                  } *r = (typeof(r))ri->d;
>  
> -                printf(" %s sched_switch prev d%u, run for %u.%uus\n",
> -                       ri->dump_header, r->domid, r->runtime / 1000,
> -                       r->runtime % 1000);
> +                printf(" %s sched_switch prev d%uv%d, run for %u.%uus\n",
> +                       ri->dump_header, r->domid, r->vcpuid,
> +                       r->runtime / 1000, r->runtime % 1000);
>              }
>              break;
>          case TRC_SCHED_SWITCH_INFNEXT:
>              if(opt.dump_all)
>              {
>                  struct {
> -                    unsigned int domid, rsince;
> +                    unsigned int domid, vcpuid, rsince;
>                      int slice;
>                  } *r = (typeof(r))ri->d;
>  
> -                printf(" %s sched_switch next d%u", ri->dump_header, 
> r->domid);
> +                printf(" %s sched_switch next d%uv%u", ri->dump_header,
> +                       r->domid, r->vcpuid);
>                  if ( r->rsince != 0 )
> -                    printf(", was runnable for %u.%uus, ", r->rsince / 1000,
> +                    printf(", was runnable for %u.%uus", r->rsince / 1000,
>                             r->rsince % 1000);
>                  if ( r->slice > 0 )
> -                    printf("next slice %u.%uus", r->slice / 1000,
> +                    printf(", next slice %u.%uus", r->slice / 1000,
>                             r->slice % 1000);
>                  printf("\n");
>              }
> diff --git a/xen/common/schedule.c b/xen/common/schedule.c
> index abe063d..5b444c4 100644
> --- a/xen/common/schedule.c
> +++ b/xen/common/schedule.c
> @@ -1390,11 +1390,11 @@ static void schedule(void)
>          return continue_running(prev);
>      }
>  
> -    TRACE_2D(TRC_SCHED_SWITCH_INFPREV,
> -             prev->domain->domain_id,
> +    TRACE_3D(TRC_SCHED_SWITCH_INFPREV,
> +             prev->domain->domain_id, prev->vcpu_id,
>               now - prev->runstate.state_entry_time);
> -    TRACE_3D(TRC_SCHED_SWITCH_INFNEXT,
> -             next->domain->domain_id,
> +    TRACE_4D(TRC_SCHED_SWITCH_INFNEXT,
> +             next->domain->domain_id, next->vcpu_id,
>               (next->runstate.state == RUNSTATE_runnable) ?
>               (now - next->runstate.state_entry_time) : 0,
>               next_slice.time);
> 


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