xen/tools: tracing: 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:

 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@citrix.com>
Acked-by: George Dunlap <george.dunlap@citrix.com>

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 72c0b2448b19eadd660a2bfbd69d3fd43591c38b..a055231847b31b4a5692e384891fb3792f26de73 100644 (file)
--- 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 2678e2a1eb4ae357e236edb1daeb7e40fedbd34a..68ffcc232f703fc2b93dbfb08fa8e3bfc46c36ea 100644 (file)
--- 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 36bbd94fe51dc26aa262c7d0dcc7ed0ed3381e6a..223a120a6518a44c9893c4c733c1f89f3ac56c5a 100644 (file)
--- 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 5ef9c373b4156fba6f7d9d66122765d987ec17fa..7f2e891e93b21a3a37b1bdf08152cbd7cdef90c2 100644 (file)
--- 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)