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

[Dario Faggioli <dario.faggioli@citrix.com>]

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.

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@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
---
 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@lists.xen.org
https://lists.xen.org/xen-devel