[RFC,v1,6/6] trace: add fair scheduling trace events

Commit Message

Volodymyr Babchuk June 12, 2020, 12:22 a.m. UTC

We are tracing each IRQ or HYP mode change and the calculated time
adjustment values.

Signed-off-by: Volodymyr Babchuk <[e-mail]>
---
 tools/xentrace/xenalyze.c  | 37 +++++++++++++++++++++++++++++++++++++
 xen/common/sched/core.c    |  9 +++++++++
 xen/include/public/trace.h |  5 +++++
 3 files changed, 51 insertions(+)

Patch

diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
index b7f4e2bea8..bcde830f0e 100644
--- a/tools/xentrace/xenalyze.c
+++ b/tools/xentrace/xenalyze.c
@@ -7546,6 +7546,43 @@  void sched_process(struct pcpu_info *p)
                 printf("\n");
             }
             break;
+        case TRC_SCHED_IRQ_ENTRY:
+        case TRC_SCHED_IRQ_LEAVE:
+            if(opt.dump_all)
+            {
+                struct {
+                    unsigned int nesting;
+                } *r = (typeof(r))ri->d;
+
+                printf(" %s sched_irq_%s nesting = %u\n", ri->dump_header,
+                       ri->event == TRC_SCHED_IRQ_ENTRY ? "entry":"leave",
+                       r->nesting);
+            }
+            break;
+        case TRC_SCHED_HYP_ENTRY:
+        case TRC_SCHED_HYP_LEAVE:
+            if(opt.dump_all)
+            {
+                struct {
+                    unsigned int domid, vcpuid;
+                } *r = (typeof(r))ri->d;
+
+                printf(" %s sched_hyp_%s d%uv%u\n", ri->dump_header,
+                       ri->event == TRC_SCHED_HYP_ENTRY ? "entry":"leave",
+                       r->domid, r->vcpuid);
+            }
+            break;
+        case TRC_SCHED_TIME_ADJ:
+            if(opt.dump_all)
+            {
+                struct {
+                    unsigned int irq, hyp;
+                } *r = (typeof(r))ri->d;
+
+                printf(" %s sched time adjust IRQ %uns HYP %uns Total %uns\n", ri->dump_header,
+                       r->irq, r->hyp, r->irq + r->hyp);
+            }
+            break;
         case TRC_SCHED_CTL:
         case TRC_SCHED_S_TIMER_FN:
         case TRC_SCHED_T_TIMER_FN:
diff --git a/xen/common/sched/core.c b/xen/common/sched/core.c
index ee6b1d9161..9e82a6a22b 100644
--- a/xen/common/sched/core.c
+++ b/xen/common/sched/core.c
@@ -925,6 +925,8 @@  void vcpu_begin_irq_handler(void)
     if (is_idle_vcpu(current))
         return;
 
+    TRACE_1D(TRC_SCHED_IRQ_ENTRY, current->irq_nesting);
+
     /* XXX: Looks like ASSERT_INTERRUPTS_DISABLED() is available only for x86 */
     if ( current->irq_nesting++ )
         return;
@@ -941,6 +943,8 @@  void vcpu_end_irq_handler(void)
 
     ASSERT(current->irq_nesting);
 
+    TRACE_1D(TRC_SCHED_IRQ_LEAVE, current->irq_nesting - 1);
+
     if ( --current->irq_nesting )
         return;
 
@@ -960,6 +964,7 @@  void vcpu_begin_hyp_task(struct vcpu *v)
 #ifndef NDEBUG
     v->in_hyp_task = true;
 #endif
+    TRACE_2D(TRC_SCHED_HYP_ENTRY, v->domain->domain_id, v->vcpu_id);
 }
 
 void vcpu_end_hyp_task(struct vcpu *v)
@@ -978,6 +983,8 @@  void vcpu_end_hyp_task(struct vcpu *v)
 #ifndef NDEBUG
     v->in_hyp_task = false;
 #endif
+    TRACE_2D(TRC_SCHED_HYP_LEAVE, v->domain->domain_id, v->vcpu_id);
+}
 
 s_time_t sched_get_time_correction(struct sched_unit *u)
 {
@@ -1003,6 +1010,8 @@  s_time_t sched_get_time_correction(struct sched_unit *u)
     sched_stat_hyp_time += hyp;
     spin_unlock_irqrestore(&sched_stat_lock, flags);
 
+    TRACE_2D(TRC_SCHED_TIME_ADJ, irq, hyp);
+
     return irq + hyp;
 }
 
diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
index d5fa4aea8d..6161980095 100644
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -117,6 +117,11 @@ 
 #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_SCHED_IRQ_ENTRY      (TRC_SCHED_VERBOSE + 18)
+#define TRC_SCHED_IRQ_LEAVE      (TRC_SCHED_VERBOSE + 19)
+#define TRC_SCHED_HYP_ENTRY      (TRC_SCHED_VERBOSE + 20)
+#define TRC_SCHED_HYP_LEAVE      (TRC_SCHED_VERBOSE + 21)
+#define TRC_SCHED_TIME_ADJ       (TRC_SCHED_VERBOSE + 22)
 
 #define TRC_DOM0_DOM_ADD         (TRC_DOM0_DOMOPS + 1)
 #define TRC_DOM0_DOM_REM         (TRC_DOM0_DOMOPS + 2)