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

[Dario Faggioli <dario.faggioli@xxxxxxxxxx>]

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