All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH 00/14] Scheduling related tracing improvements
@ 2016-02-05 18:33 Dario Faggioli
  2016-02-05 18:33 ` [PATCH 01/14] xen: sched: __runq_tickle takes a useless cpu parameter Dario Faggioli
                   ` (13 more replies)
  0 siblings, 14 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:33 UTC (permalink / raw)
  To: xen-devel
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Tianyang Chen,
	Ian Jackson, Meng Xu

Hi everyone,

This, hopefully, simple series aims at making it easier to look at and
interpret hypervisor scheduling related traces.

In fact, it includes improvements for both how xentrace_format and xenalyze
decode and pretty print a trace collected with scheduling events enabled,
either generic scheduling events or specific events from one of our scheduler.

In fact:
 - patches 11-14 improve xenalyze own understanding and dumping of scheduling
   events
 - patches 07-10 improve the 'formats' file that should be used for
   xentrace_format, for the same purpose
 - patches 04-06 are small hypervisor changes required for making the
   improvement possible
 - patches 02-03 are refinements on the position of some trace points
 - patch 01 is not really related to this series, it's just Credit1's
   code cleanup

After this series, for instance, 'xenalyze --dump-all' looks like this:

   0.000575665 -..--..x ..... . d?v? runstate_change d0v10 runnable->running
   0.000621704 -..--..x ..... . d0v10 vcpu_block d0v10
   0.000623592 -..--..x ..... . d0v10 sched_switch prev d0, run for 48.488us
   0.000623792 -..--..x ..... . d0v10 sched_switch next d32767, was runnable for 48.488us, 
   0.000624017 -..--..x ..... . d0v10 sched_switch prev d0v10 next d32767v7
   0.000624309 -..--..x ..... . d0v10 runstate_change d0v10 running->blocked
   0.000624650 -..--..x ..... . d?v? runstate_change d32767v7 runnable->running
   0.000806574 x..--..- ..... . d32767v0 vcpu_wake d0v0
   0.000806954 x..--..- ..... . d32767v0 runstate_change d0v0 blocked->runnable
   0.000807697 x..--..- ..... . d32767v0 csched:runq_tickle, cpu 0
   0.000810162 x..--..- ..... . d32767v0 sched_switch prev d32767, run for 279.105us
   0.000810340 x..--..- ..... . d32767v0 sched_switch next d0, was runnable for 2.516us, next slice 30000.0us
   0.000810625 x..--..- ..... . d32767v0 sched_switch prev d32767v0 next d0v0
   0.000810850 x..--..- ..... . d32767v0 runstate_change d32767v0 running->runnable
   0.000811205 x..--..- ..... . d?v? runstate_change d0v0 runnable->running
   0.000833005 |..--..- ..x.. . d32768v11 vcpu_wake d0v8
   0.000833596 |..--..- ..x.. . d32768v11 runstate_change d0v8 blocked->runnable

Thanks and Regards,
Dario
---
Dario Faggioli (14):
      xen: sched: __runq_tickle takes a useless cpu parameter
      xen: sched: move up the trace record for vcpu_wake and vcpu_sleep
      xen: sched: fi position of TRC_SCHED_DOM_{ADD,REM}
      xen: credit2: pack trace data better for xentrace_format
      xen: RTDS: pack trace data better for xentrace_format
      xen: sched: tracing: enable TSC tracing for all events
      xentrace: formats: update format of scheduling events
      xentrace: formats: add events from Credit scheduler
      xentrace: formats: add events from Credit2 scheduler
      xentrace: formats: add events from RTDS scheduler
      xenalyze: handle scheduling events
      xenalyze: handle Credit1 scheduler events
      xenalyze: handle Credit2 scheduler events
      xenalyze: handle RTDS scheduler events


 tools/xentrace/formats     |   44 ++++-
 tools/xentrace/xenalyze.c  |  373 ++++++++++++++++++++++++++++++++++++++++----
 xen/common/domain.c        |    1 
 xen/common/sched_credit.c  |   12 +
 xen/common/sched_credit2.c |   22 +--
 xen/common/sched_rt.c      |   29 +--
 xen/common/schedule.c      |   20 +-
 7 files changed, 411 insertions(+), 90 deletions(-)
--
<<This happens because I choose it to happen!>> (Raistlin Majere)
-----------------------------------------------------------------
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK)

^ permalink raw reply	[flat|nested] 31+ messages in thread

* [PATCH 01/14] xen: sched: __runq_tickle takes a useless cpu parameter
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
@ 2016-02-05 18:33 ` Dario Faggioli
  2016-02-15 16:14   ` Konrad Rzeszutek Wilk
  2016-02-05 18:33 ` [PATCH 02/14] xen: sched: move up the trace record for vcpu_wake and vcpu_sleep Dario Faggioli
                   ` (12 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:33 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap

as it is always acts on v->processor of the vcpu because
of which we are tickling.

Getting rid of it makes the code easier to understand
and better looking.

While there, remove a spurious blank line.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@citrix.com>
---
 xen/common/sched_credit.c |   10 ++++------
 1 file changed, 4 insertions(+), 6 deletions(-)

diff --git a/xen/common/sched_credit.c b/xen/common/sched_credit.c
index 671bbee..5279b92 100644
--- a/xen/common/sched_credit.c
+++ b/xen/common/sched_credit.c
@@ -360,9 +360,9 @@ boolean_param("tickle_one_idle_cpu", opt_tickle_one_idle);
 
 DEFINE_PER_CPU(unsigned int, last_tickle_cpu);
 
-static inline void
-__runq_tickle(unsigned int cpu, struct csched_vcpu *new)
+static inline void __runq_tickle(struct csched_vcpu *new)
 {
+    unsigned int cpu = new->vcpu->processor;
     struct csched_vcpu * const cur = CSCHED_VCPU(curr_on_cpu(cpu));
     struct csched_private *prv = CSCHED_PRIV(per_cpu(scheduler, cpu));
     cpumask_t mask, idle_mask, *online;
@@ -375,7 +375,6 @@ __runq_tickle(unsigned int cpu, struct csched_vcpu *new)
     cpumask_and(&idle_mask, prv->idlers, online);
     idlers_empty = cpumask_empty(&idle_mask);
 
-
     /*
      * If the pcpu is idle, or there are no idlers and the new
      * vcpu is a higher priority than the old vcpu, run it here.
@@ -980,11 +979,10 @@ static void
 csched_vcpu_wake(const struct scheduler *ops, struct vcpu *vc)
 {
     struct csched_vcpu * const svc = CSCHED_VCPU(vc);
-    const unsigned int cpu = vc->processor;
 
     BUG_ON( is_idle_vcpu(vc) );
 
-    if ( unlikely(curr_on_cpu(cpu) == vc) )
+    if ( unlikely(curr_on_cpu(vc->processor) == vc) )
     {
         SCHED_STAT_CRANK(vcpu_wake_running);
         return;
@@ -1028,7 +1026,7 @@ csched_vcpu_wake(const struct scheduler *ops, struct vcpu *vc)
 
     /* Put the VCPU on the runq and tickle CPUs */
     __runq_insert(svc);
-    __runq_tickle(cpu, svc);
+    __runq_tickle(svc);
 }
 
 static void

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 02/14] xen: sched: move up the trace record for vcpu_wake and vcpu_sleep
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
  2016-02-05 18:33 ` [PATCH 01/14] xen: sched: __runq_tickle takes a useless cpu parameter Dario Faggioli
@ 2016-02-05 18:33 ` Dario Faggioli
  2016-02-15 16:18   ` Konrad Rzeszutek Wilk
  2016-02-05 18:33 ` [PATCH 03/14] xen: sched: fi position of TRC_SCHED_DOM_{ADD, REM} Dario Faggioli
                   ` (11 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:33 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap

vcpu_wake() and vcpu_sleep() are called before the specific
schedulers wakeup and sleep routines (in fact, it is them
that calls those specific routine).

Make the trace reflect that, by moving the records up. In
fact, it is more natural and easy to find the record of
the event (e.g., the wakeup) *before* the records of the
actions that deals with the event itself.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@citrix.com>
---
 xen/common/schedule.c |   16 ++++++++++------
 1 file changed, 10 insertions(+), 6 deletions(-)

diff --git a/xen/common/schedule.c b/xen/common/schedule.c
index 7306d71..c87922f 100644
--- a/xen/common/schedule.c
+++ b/xen/common/schedule.c
@@ -381,7 +381,11 @@ void sched_destroy_domain(struct domain *d)
 void vcpu_sleep_nosync(struct vcpu *v)
 {
     unsigned long flags;
-    spinlock_t *lock = vcpu_schedule_lock_irqsave(v, &flags);
+    spinlock_t *lock;
+
+    TRACE_2D(TRC_SCHED_SLEEP, v->domain->domain_id, v->vcpu_id);
+
+    lock = vcpu_schedule_lock_irqsave(v, &flags);
 
     if ( likely(!vcpu_runnable(v)) )
     {
@@ -392,8 +396,6 @@ void vcpu_sleep_nosync(struct vcpu *v)
     }
 
     vcpu_schedule_unlock_irqrestore(lock, flags, v);
-
-    TRACE_2D(TRC_SCHED_SLEEP, v->domain->domain_id, v->vcpu_id);
 }
 
 void vcpu_sleep_sync(struct vcpu *v)
@@ -409,7 +411,11 @@ void vcpu_sleep_sync(struct vcpu *v)
 void vcpu_wake(struct vcpu *v)
 {
     unsigned long flags;
-    spinlock_t *lock = vcpu_schedule_lock_irqsave(v, &flags);
+    spinlock_t *lock;
+
+    TRACE_2D(TRC_SCHED_WAKE, v->domain->domain_id, v->vcpu_id);
+
+    lock = vcpu_schedule_lock_irqsave(v, &flags);
 
     if ( likely(vcpu_runnable(v)) )
     {
@@ -424,8 +430,6 @@ void vcpu_wake(struct vcpu *v)
     }
 
     vcpu_schedule_unlock_irqrestore(lock, flags, v);
-
-    TRACE_2D(TRC_SCHED_WAKE, v->domain->domain_id, v->vcpu_id);
 }
 
 void vcpu_unblock(struct vcpu *v)

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 03/14] xen: sched: fi position of TRC_SCHED_DOM_{ADD, REM}
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
  2016-02-05 18:33 ` [PATCH 01/14] xen: sched: __runq_tickle takes a useless cpu parameter Dario Faggioli
  2016-02-05 18:33 ` [PATCH 02/14] xen: sched: move up the trace record for vcpu_wake and vcpu_sleep Dario Faggioli
@ 2016-02-05 18:33 ` Dario Faggioli
  2016-02-15 16:22   ` Konrad Rzeszutek Wilk
  2016-02-05 18:33 ` [PATCH 04/14] xen: credit2: pack trace data better for xentrace_format Dario Faggioli
                   ` (10 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:33 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap

so that they actually live in the functions that
do the scheduling related domain initialization and
destruction.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
---
 xen/common/domain.c   |    1 -
 xen/common/schedule.c |    4 ++--
 2 files changed, 2 insertions(+), 3 deletions(-)

diff --git a/xen/common/domain.c b/xen/common/domain.c
index 425767c..ddc7484 100644
--- a/xen/common/domain.c
+++ b/xen/common/domain.c
@@ -867,7 +867,6 @@ void domain_destroy(struct domain *d)
     cpupool_rm_domain(d);
 
     /* Delete from task list and task hashtable. */
-    TRACE_1D(TRC_SCHED_DOM_REM, d->domain_id);
     spin_lock(&domlist_update_lock);
     pd = &domain_list;
     while ( *pd != d ) 
diff --git a/xen/common/schedule.c b/xen/common/schedule.c
index c87922f..27695e3 100644
--- a/xen/common/schedule.c
+++ b/xen/common/schedule.c
@@ -241,8 +241,6 @@ int sched_init_vcpu(struct vcpu *v, unsigned int processor)
     if ( v->sched_priv == NULL )
         return 1;
 
-    TRACE_2D(TRC_SCHED_DOM_ADD, v->domain->domain_id, v->vcpu_id);
-
     /* Idle VCPUs are scheduled immediately, so don't put them in runqueue. */
     if ( is_idle_domain(d) )
     {
@@ -369,12 +367,14 @@ void sched_destroy_vcpu(struct vcpu *v)
 int sched_init_domain(struct domain *d)
 {
     SCHED_STAT_CRANK(dom_init);
+    TRACE_1D(TRC_SCHED_DOM_ADD, d->domain_id);
     return SCHED_OP(DOM2OP(d), init_domain, d);
 }
 
 void sched_destroy_domain(struct domain *d)
 {
     SCHED_STAT_CRANK(dom_destroy);
+    TRACE_1D(TRC_SCHED_DOM_REM, d->domain_id);
     SCHED_OP(DOM2OP(d), destroy_domain, d);
 }

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 04/14] xen: credit2: pack trace data better for xentrace_format
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (2 preceding siblings ...)
  2016-02-05 18:33 ` [PATCH 03/14] xen: sched: fi position of TRC_SCHED_DOM_{ADD, REM} Dario Faggioli
@ 2016-02-05 18:33 ` Dario Faggioli
  2016-02-15 16:29   ` Konrad Rzeszutek Wilk
  2016-02-05 18:34 ` [PATCH 05/14] xen: RTDS: " Dario Faggioli
                   ` (9 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:33 UTC (permalink / raw)
  To: xen-devel; +Cc: Olaf Hering, George Dunlap

when tracing runstate changes, the vcpu and domain IDs
are encoded in the lower and higher, respectively, parts
of a 32 bits integer. When decoding a trace with
xentrace_format, this makes it possible to display
such events like this:

CPU0  833435853624 (+     768)  running_to_runnable [ dom:vcpu = 0x7fff0000 ]
CPU0  833435854416 (+     792)  runnable_to_running [ dom:vcpu = 0x00000007 ]

For consistency, we should do the same when displaying
the events coming from the Credit2 scheduler (when using
the same tool), and to do that, we need to invert the
order in which the fields are being put in the trace
struct right now.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 xen/common/sched_credit2.c |   16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/xen/common/sched_credit2.c b/xen/common/sched_credit2.c
index 78220a7..cf40f68 100644
--- a/xen/common/sched_credit2.c
+++ b/xen/common/sched_credit2.c
@@ -382,7 +382,7 @@ __update_svc_load(const struct scheduler *ops,
 
     {
         struct {
-            unsigned dom:16,vcpu:16;
+            unsigned vcpu:16, dom:16;
             unsigned v_avgload:32;
         } d;
         d.dom = svc->vcpu->domain->domain_id;
@@ -450,7 +450,7 @@ runq_insert(const struct scheduler *ops, unsigned int cpu, struct csched2_vcpu *
 
     {
         struct {
-            unsigned dom:16,vcpu:16;
+            unsigned vcpu:16, dom:16;
             unsigned pos;
         } d;
         d.dom = svc->vcpu->domain->domain_id;
@@ -536,7 +536,7 @@ runq_tickle(const struct scheduler *ops, unsigned int cpu, struct csched2_vcpu *
 
         /* TRACE */ {
             struct {
-                unsigned dom:16,vcpu:16;
+                unsigned vcpu:16, dom:16;
                 unsigned credit;
             } d;
             d.dom = cur->vcpu->domain->domain_id;
@@ -561,9 +561,9 @@ tickle:
 
     /* TRACE */ {
         struct {
-            unsigned cpu:8;
+            unsigned cpu:16, pad:16;
         } d;
-        d.cpu = ipid;
+        d.cpu = ipid; d.pad = 0;
         trace_var(TRC_CSCHED2_TICKLE, 0,
                   sizeof(d),
                   (unsigned char *)&d);
@@ -634,7 +634,7 @@ static void reset_credit(const struct scheduler *ops, int cpu, s_time_t now,
 
         /* TRACE */ {
             struct {
-                unsigned dom:16,vcpu:16;
+                unsigned vcpu:16, dom:16;
                 unsigned credit_start, credit_end;
                 unsigned multiplier;
             } d;
@@ -683,7 +683,7 @@ void burn_credits(struct csched2_runqueue_data *rqd, struct csched2_vcpu *svc, s
     /* TRACE */
     {
         struct {
-            unsigned dom:16,vcpu:16;
+            unsigned vcpu:16, dom:16;
             unsigned credit;
             int delta;
         } d;
@@ -812,7 +812,7 @@ __runq_assign(struct csched2_vcpu *svc, struct csched2_runqueue_data *rqd)
     /* TRACE */
     {
         struct {
-            unsigned dom:16,vcpu:16;
+            unsigned vcpu:16, dom:16;
             unsigned rqi:16;
         } d;
         d.dom = svc->vcpu->domain->domain_id;

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 05/14] xen: RTDS: pack trace data better for xentrace_format
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (3 preceding siblings ...)
  2016-02-05 18:33 ` [PATCH 04/14] xen: credit2: pack trace data better for xentrace_format Dario Faggioli
@ 2016-02-05 18:34 ` Dario Faggioli
  2016-02-15 16:31   ` Konrad Rzeszutek Wilk
  2016-02-05 18:34 ` [PATCH 06/14] xen: sched: tracing: enable TSC tracing for all events Dario Faggioli
                   ` (8 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:34 UTC (permalink / raw)
  To: xen-devel; +Cc: Olaf Hering, Tianyang Chen, Meng Xu, George Dunlap

when tracing runstate changes, the vcpu and domain IDs
are encoded in the lower and higher, respectively, parts
of a 32 bits integer. When decoding a trace with
xentrace_format, this makes it possible to display
such events like this:

CPU0  833435853624 (+     768)  running_to_runnable [ dom:vcpu = 0x7fff0000 ]
CPU0  833435854416 (+     792)  runnable_to_running [ dom:vcpu = 0x00000007 ]

For consistency, we should do the same when displaying
the events coming from the RTDS scheduler (when using
the same tool), and to do that, we need to invert the
order in which the fields are being put in the trace
struct right now.

While there, we also:
 - fix the use of TRC_RTDS_SCHED_TASKLET (it should
   only be involved when a tasklet is scheduled, not
   _every_ time rt_schedule() is invoked!);
 - remove a very chatty and useless (nothing has been
   picked!) use of TRC_RTDS_RUNQ_PICK.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@citrix.com>
Cc: Meng Xu <xumengpanda@gmail.com>
Cc: Tianyang Chen <tiche@seas.upenn.edu>
Cc: Olaf Hering <olaf@aepfle.de>
---
 xen/common/sched_rt.c |   27 ++++-----------------------
 1 file changed, 4 insertions(+), 23 deletions(-)

diff --git a/xen/common/sched_rt.c b/xen/common/sched_rt.c
index 2e5430f..53de6d6 100644
--- a/xen/common/sched_rt.c
+++ b/xen/common/sched_rt.c
@@ -362,7 +362,7 @@ rt_update_deadline(s_time_t now, struct rt_vcpu *svc)
     /* TRACE */
     {
         struct {
-            unsigned dom:16,vcpu:16;
+            unsigned vcpu:16, dom:16;
             unsigned cur_deadline_lo, cur_deadline_hi;
             unsigned cur_budget_lo, cur_budget_hi;
         } d;
@@ -711,7 +711,7 @@ burn_budget(const struct scheduler *ops, struct rt_vcpu *svc, s_time_t now)
     /* TRACE */
     {
         struct {
-            unsigned dom:16, vcpu:16;
+            unsigned vcpu:16, dom:16;
             unsigned cur_budget_lo;
             unsigned cur_budget_hi;
             int delta;
@@ -763,7 +763,7 @@ __runq_pick(const struct scheduler *ops, const cpumask_t *mask)
         if( svc != NULL )
         {
             struct {
-                unsigned dom:16, vcpu:16;
+                unsigned vcpu:16, dom:16;
                 unsigned cur_deadline_lo, cur_deadline_hi;
                 unsigned cur_budget_lo, cur_budget_hi;
             } d;
@@ -777,8 +777,6 @@ __runq_pick(const struct scheduler *ops, const cpumask_t *mask)
                       sizeof(d),
                       (unsigned char *) &d);
         }
-        else
-            trace_var(TRC_RTDS_RUNQ_PICK, 1, 0, NULL);
     }
 
     return svc;
@@ -845,6 +843,7 @@ rt_schedule(const struct scheduler *ops, s_time_t now, bool_t tasklet_work_sched
 
     if ( tasklet_work_scheduled )
     {
+        trace_var(TRC_RTDS_SCHED_TASKLET, 1, 0,  NULL);
         snext = rt_vcpu(idle_vcpu[cpu]);
     }
     else
@@ -885,24 +884,6 @@ rt_schedule(const struct scheduler *ops, s_time_t now, bool_t tasklet_work_sched
     ret.time = MIN(snext->budget, MAX_SCHEDULE); /* sched quantum */
     ret.task = snext->vcpu;
 
-    /* TRACE */
-    {
-        struct {
-            unsigned dom:16,vcpu:16;
-            unsigned cur_deadline_lo, cur_deadline_hi;
-            unsigned cur_budget_lo, cur_budget_hi;
-        } d;
-        d.dom = snext->vcpu->domain->domain_id;
-        d.vcpu = snext->vcpu->vcpu_id;
-        d.cur_deadline_lo = (unsigned) snext->cur_deadline;
-        d.cur_deadline_hi = (unsigned) (snext->cur_deadline >> 32);
-        d.cur_budget_lo = (unsigned) snext->cur_budget;
-        d.cur_budget_hi = (unsigned) (snext->cur_budget >> 32);
-        trace_var(TRC_RTDS_SCHED_TASKLET, 1,
-                  sizeof(d),
-                  (unsigned char *)&d);
-    }
-
     return ret;
 }

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 06/14] xen: sched: tracing: enable TSC tracing for all events
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (4 preceding siblings ...)
  2016-02-05 18:34 ` [PATCH 05/14] xen: RTDS: " Dario Faggioli
@ 2016-02-05 18:34 ` Dario Faggioli
  2016-02-15 16:32   ` Konrad Rzeszutek Wilk
  2016-02-05 18:34 ` [PATCH 07/14] xentrace: formats: update format of scheduling events Dario Faggioli
                   ` (7 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:34 UTC (permalink / raw)
  To: xen-devel; +Cc: Olaf Hering, Tianyang Chen, Meng Xu, George Dunlap

it is enabled for pretty much all of them already.
There were just a few that had it disabled.

When tracing a scheduler, timing information is
really important, so enable it everywhere scheduling
related.

Note that this was not really a problem if looking
at the traces with xenalyze, but it was if using
xentrace_format.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@citrix.com>
Cc: Meng Xu <xumengpanda@gmail.com>
Cc: Tianyang Chen <tiche@seas.upenn.edu>
Cc: Olaf Hering <olaf@aepfle.de>
---
 xen/common/sched_credit.c  |    2 +-
 xen/common/sched_credit2.c |    6 +++---
 xen/common/sched_rt.c      |    2 +-
 3 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/xen/common/sched_credit.c b/xen/common/sched_credit.c
index 5279b92..bd2f37f 100644
--- a/xen/common/sched_credit.c
+++ b/xen/common/sched_credit.c
@@ -476,7 +476,7 @@ static inline void __runq_tickle(struct csched_vcpu *new)
         {
             /* Avoid TRACE_*: saves checking !tb_init_done each step */
             for_each_cpu(cpu, &mask)
-                __trace_var(TRC_CSCHED_TICKLE, 0, sizeof(cpu), &cpu);
+                __trace_var(TRC_CSCHED_TICKLE, 1, sizeof(cpu), &cpu);
         }
 
         /* Send scheduler interrupts to designated CPUs */
diff --git a/xen/common/sched_credit2.c b/xen/common/sched_credit2.c
index cf40f68..2934e26 100644
--- a/xen/common/sched_credit2.c
+++ b/xen/common/sched_credit2.c
@@ -456,7 +456,7 @@ runq_insert(const struct scheduler *ops, unsigned int cpu, struct csched2_vcpu *
         d.dom = svc->vcpu->domain->domain_id;
         d.vcpu = svc->vcpu->vcpu_id;
         d.pos = pos;
-        trace_var(TRC_CSCHED2_RUNQ_POS, 0,
+        trace_var(TRC_CSCHED2_RUNQ_POS, 1,
                   sizeof(d),
                   (unsigned char *)&d);
     }
@@ -564,7 +564,7 @@ tickle:
             unsigned cpu:16, pad:16;
         } d;
         d.cpu = ipid; d.pad = 0;
-        trace_var(TRC_CSCHED2_TICKLE, 0,
+        trace_var(TRC_CSCHED2_TICKLE, 1,
                   sizeof(d),
                   (unsigned char *)&d);
     }
@@ -1721,7 +1721,7 @@ csched2_schedule(
      */
     if ( tasklet_work_scheduled )
     {
-        trace_var(TRC_CSCHED2_SCHED_TASKLET, 0, 0,  NULL);
+        trace_var(TRC_CSCHED2_SCHED_TASKLET, 1, 0,  NULL);
         snext = CSCHED2_VCPU(idle_vcpu[cpu]);
     }
     else
diff --git a/xen/common/sched_rt.c b/xen/common/sched_rt.c
index 53de6d6..33ac9de 100644
--- a/xen/common/sched_rt.c
+++ b/xen/common/sched_rt.c
@@ -985,7 +985,7 @@ out:
         } d;
         d.cpu = cpu_to_tickle;
         d.pad = 0;
-        trace_var(TRC_RTDS_TICKLE, 0,
+        trace_var(TRC_RTDS_TICKLE, 1,
                   sizeof(d),
                   (unsigned char *)&d);
     }

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 07/14] xentrace: formats: update format of scheduling events
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (5 preceding siblings ...)
  2016-02-05 18:34 ` [PATCH 06/14] xen: sched: tracing: enable TSC tracing for all events Dario Faggioli
@ 2016-02-05 18:34 ` Dario Faggioli
  2016-02-15 16:38   ` Konrad Rzeszutek Wilk
  2016-02-05 18:34 ` [PATCH 08/14] xentrace: formats: add events from Credit scheduler Dario Faggioli
                   ` (6 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:34 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap, Wei Liu, Olaf Hering, Ian Jackson, Ian Campbell

to include the vcpu IDs, in a way that matches
how the "dom:vcpu" couple is displayed in other
events (runstate changes).

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Ian Campbell <ian.campbell@citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 tools/xentrace/formats |   18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 5d7b72a..5257cf0 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -19,22 +19,22 @@
 0x00021311  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  offline_to_runnable [ dom:vcpu = 0x%(1)08x ]
 0x00021321  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  offline_to_blocked  [ dom:vcpu = 0x%(1)08x ]
 
-0x00028001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_add_domain  [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x00028002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_rem_domain  [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x00028003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_sleep      [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x00028004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_wake       [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x00028005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_yield          [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x00028006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_block          [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
-0x00022006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_block          [ dom:vcpu = 0x%(1)08x, domid = 0x%(2)08x ]
-0x00028007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown	  [ domid = 0x%(1)08x, edomid = 0x%(2)08x, reason = 0x%(3)08x ]
+0x00028001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_add_domain  [ domid = 0x%(1)08x ]
+0x00028002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_rem_domain  [ domid = 0x%(1)08x ]
+0x00028003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_sleep      [ dom:vcpu = 0x%(1)04x%(2)04x ]
+0x00028004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_wake       [ dom:vcpu = 0x%(1)04x%(2)04x ]
+0x00028005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_yield          [ dom:vcpu = 0x%(1)04x%(2)04x ]
+0x00028006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_block          [ dom:vcpu = 0x%(1)04x%(2)04x ]
+0x00028007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown	  [ dom:vcpu = 0x%(1)04x%(2)04x, reason = 0x%(3)08x ]
 0x00028008  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_ctl
 0x00028009  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_adjdom      [ domid = 0x%(1)08x ]
-0x0002800a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  __enter_scheduler [ prev<domid:edomid> = 0x%(1)08x : 0x%(2)08x, next<domid:edomid> = 0x%(3)08x : 0x%(4)08x ]
+0x0002800a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  __enter_scheduler [ prev<dom:vcpu> = 0x%(1)04x%(2)04x, next<dom:vcpu> = 0x%(3)04x%(4)04x ]
 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 ]
+0x00028010  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown_code [ dom:vcpu = 0x%(1)04x%(2)04x, reason = 0x%(3)08x ]
 
 0x00081001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMENTRY
 0x00081002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(2)08x ]

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 08/14] xentrace: formats: add events from Credit scheduler
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (6 preceding siblings ...)
  2016-02-05 18:34 ` [PATCH 07/14] xentrace: formats: update format of scheduling events Dario Faggioli
@ 2016-02-05 18:34 ` Dario Faggioli
  2016-02-15 16:40   ` Konrad Rzeszutek Wilk
  2016-02-05 18:34 ` [PATCH 09/14] xentrace: formats: add events from Credit2 scheduler Dario Faggioli
                   ` (5 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:34 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap, Wei Liu, Olaf Hering, Ian Jackson, Ian Campbell

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Ian Campbell <ian.campbell@citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 tools/xentrace/formats |    7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index 5257cf0..a5636e9 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -36,6 +36,13 @@
 0x0002800f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infnext    [ new_domid = 0x%(1)08x, time = %(2)d, r_time = %(3)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
+0x00022002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:account_start [ dom:vcpu = 0x%(1)04x%(2)04x, active = %(3)d ]
+0x00022003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:account_stop  [ dom:vcpu = 0x%(1)04x%(2)04x, active = %(3)d ]
+0x00022004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:stolen_vcpu   [ dom:vcpu = 0x%(2)04x%(3)04x, from = %(1)d ]
+0x00022005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:picked_cpu    [ dom:vcpu = 0x%(1)04x%(2)04x, cpu = %(3)d ]
+0x00022006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:tickle        [ cpu = %(1)d ]
+
 0x00081001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMENTRY
 0x00081002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(2)08x ]
 0x00081102  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(3)08x%(2)08x ]

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 09/14] xentrace: formats: add events from Credit2 scheduler
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (7 preceding siblings ...)
  2016-02-05 18:34 ` [PATCH 08/14] xentrace: formats: add events from Credit scheduler Dario Faggioli
@ 2016-02-05 18:34 ` Dario Faggioli
  2016-02-15 16:44   ` Konrad Rzeszutek Wilk
  2016-02-05 18:35 ` [PATCH 10/14] xentrace: formats: add events from RTDS scheduler Dario Faggioli
                   ` (4 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:34 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap, Wei Liu, Olaf Hering, Ian Jackson, Ian Campbell

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Ian Campbell <ian.campbell@citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 tools/xentrace/formats |   13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index a5636e9..b8ec06b 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -43,6 +43,19 @@
 0x00022005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:picked_cpu    [ dom:vcpu = 0x%(1)04x%(2)04x, cpu = %(3)d ]
 0x00022006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:tickle        [ cpu = %(1)d ]
 
+0x00022201  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:tick
+0x00022202  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:runq_pos       [ dom:vcpu = 0x%(1)08x, pos = %(2)d]
+0x00022203  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:credit burn    [ dom:vcpu = 0x%(1)08x, credit = %(2)d, delta = %(3)d ]
+0x00022204  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:credit_add
+0x00022205  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:tickle_check   [ dom:vcpu = 0x%(1)08x, credit = %(2)d ]
+0x00022206  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:tickle         [ cpu = %(1)d ]
+0x00022207  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:credit_reset   [ dom:vcpu = 0x%(1)08x, cr_start = %(2)d, cr_end = %(3)d, mult = %(4)d ]
+0x00022208  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:sched_tasklet
+0x00022209  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:update_load
+0x0002220a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:runq_assign    [ dom:vcpu = 0x%(1)08x, rq_idx = %(2)d ]
+0x0002220b  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:updt_vcpu_load [ dom:vcpu = 0x%(1)08x, avgload = %(2)d ]
+0x0002220c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:updt_runq_load [ rq_load[4]:rq_avgload[28] = 0x%(1)08x, rq_idx[4]:b_avgload[28] = 0x%(2)08x ]
+
 0x00081001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMENTRY
 0x00081002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(2)08x ]
 0x00081102  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(3)08x%(2)08x ]

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 10/14] xentrace: formats: add events from RTDS scheduler
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (8 preceding siblings ...)
  2016-02-05 18:34 ` [PATCH 09/14] xentrace: formats: add events from Credit2 scheduler Dario Faggioli
@ 2016-02-05 18:35 ` Dario Faggioli
  2016-02-05 18:35 ` [PATCH 11/14] xenalyze: handle scheduling events Dario Faggioli
                   ` (3 subsequent siblings)
  13 siblings, 0 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:35 UTC (permalink / raw)
  To: xen-devel
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Tianyang Chen,
	Ian Jackson, Meng Xu

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Meng Xu <xumengpanda@gmail.com>
Cc: Tianyang Chen <tiche@seas.upenn.edu>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Ian Campbell <ian.campbell@citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 tools/xentrace/formats |    6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index b8ec06b..2e5108f 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -56,6 +56,12 @@
 0x0002220b  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:updt_vcpu_load [ dom:vcpu = 0x%(1)08x, avgload = %(2)d ]
 0x0002220c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:updt_runq_load [ rq_load[4]:rq_avgload[28] = 0x%(1)08x, rq_idx[4]:b_avgload[28] = 0x%(2)08x ]
 
+0x00022801  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtds:tickle        [ cpu = %(1)d ]
+0x00022802  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtds:runq_pick     [ dom:vcpu = 0x%(1)08x, cur_deadline = 0x%(3)08x%(2)08x, cur_budget = 0x%(5)08x%(4)08x ]
+0x00022803  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtds:burn_budget   [ dom:vcpu = 0x%(1)08x, cur_budget = 0x%(3)08x%(2)08x, delta = %(4)d ]
+0x00022804  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtds:repl_budget   [ dom:vcpu = 0x%(1)08x, cur_deadline = 0x%(3)08x%(2)08x, cur_budget = 0x%(5)08x%(4)08x ]
+0x00022805  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  rtds:sched_tasklet
+
 0x00081001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMENTRY
 0x00081002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(2)08x ]
 0x00081102  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(3)08x%(2)08x ]

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 11/14] xenalyze: handle scheduling events
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (9 preceding siblings ...)
  2016-02-05 18:35 ` [PATCH 10/14] xentrace: formats: add events from RTDS scheduler Dario Faggioli
@ 2016-02-05 18:35 ` Dario Faggioli
  2016-02-15 16:51   ` Konrad Rzeszutek Wilk
  2016-02-05 18:35 ` [PATCH 12/14] xenalyze: handle Credit1 scheduler events Dario Faggioli
                   ` (2 subsequent siblings)
  13 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:35 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap, Wei Liu, Olaf Hering, Ian Jackson, Ian Campbell

so the trace will show properly decoded info,
rather than just a bunch of hex codes.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Ian Campbell <ian.campbell@citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 tools/xentrace/xenalyze.c |  156 ++++++++++++++++++++++++++++++++++++---------
 1 file changed, 126 insertions(+), 30 deletions(-)

diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
index 6520790..be698aa 100644
--- a/tools/xentrace/xenalyze.c
+++ b/tools/xentrace/xenalyze.c
@@ -1519,27 +1519,6 @@ struct pv_data {
 };
 
 /* Sched data */
-
-enum {
-    SCHED_DOM_ADD=1,
-    SCHED_DOM_REM,
-    SCHED_SLEEP,
-    SCHED_WAKE,
-    SCHED_YIELD,
-    SCHED_BLOCK,
-    SCHED_SHUTDOWN,
-    SCHED_CTL,
-    SCHED_ADJDOM,
-    SCHED_SWITCH,
-    SCHED_S_TIMER_FN,
-    SCHED_T_TIMER_FN,
-    SCHED_DOM_TIMER_FN,
-    SCHED_SWITCH_INFPREV,
-    SCHED_SWITCH_INFNEXT,
-    SCHED_SHUTDOWN_CODE,
-    SCHED_MAX
-};
-
 enum {
     RUNSTATE_RUNNING=0,
     RUNSTATE_RUNNABLE,
@@ -7431,6 +7410,17 @@ no_update:
     return;
 }
 
+void dump_sched_switch(struct record_info *ri)
+{
+    struct {
+        unsigned int prev_dom, prev_vcpu, next_dom, next_vcpu;
+    } * r = (typeof(r))ri->d;
+
+    printf(" %s sched_switch prev d%uv%u next d%uv%u\n",
+           ri->dump_header, r->prev_dom, r->prev_vcpu,
+           r->next_dom, r->next_vcpu);
+}
+
 void sched_switch_process(struct pcpu_info *p)
 {
     struct vcpu_data *prev, *next;
@@ -7440,10 +7430,7 @@ void sched_switch_process(struct pcpu_info *p)
     } * r = (typeof(r))ri->d;
 
     if(opt.dump_all)
-        printf("%s sched_switch prev d%uv%u next d%uv%u\n",
-               ri->dump_header,
-               r->prev_dom, r->prev_vcpu,
-               r->next_dom, r->next_vcpu);
+        dump_sched_switch(ri);
 
     if(r->prev_vcpu > MAX_CPUS)
     {
@@ -7559,6 +7546,14 @@ void sched_summary_domain(struct domain_data *d)
     }
 }
 
+void dump_sched_vcpu_action(struct record_info *ri, const char *action)
+{
+    struct {
+        unsigned int domid, vcpuid;
+    } * r = (typeof(r))ri->d;
+
+    printf(" %s %s d%uv%u\n", ri->dump_header, action, r->domid, r->vcpuid);
+}
 
 void sched_process(struct pcpu_info *p)
 {
@@ -7573,13 +7568,114 @@ void sched_process(struct pcpu_info *p)
         default:
             process_generic(&p->ri);
         }
-    } else {
-        if(ri->evt.sub == 1)
-            sched_runstate_process(p);
-        else {
-            UPDATE_VOLUME(p, sched_verbose, ri->size);
+        return;
+    }
+
+    if(ri->evt.sub == 1) {
+        /* TRC_SCHED_MIN */
+        sched_runstate_process(p);
+    } else if (ri->evt.sub == 8) {
+        /* TRC_SCHED_VERBOSE */
+        switch(ri->event)
+        {
+        case TRC_SCHED_DOM_ADD:
+            if(opt.dump_all) {
+                struct {
+                    unsigned int domid;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s domain create d%u\n", ri->dump_header, r->domid);
+            }
+            break;
+        case TRC_SCHED_DOM_REM:
+            if(opt.dump_all) {
+                struct {
+                    unsigned int domid, vcpuid;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s domain destroy d%u\n", ri->dump_header, r->domid);
+            }
+            break;
+        case TRC_SCHED_SLEEP:
+            if(opt.dump_all)
+                dump_sched_vcpu_action(ri, "vcpu_sleep");
+            break;
+        case TRC_SCHED_WAKE:
+            if(opt.dump_all)
+                dump_sched_vcpu_action(ri, "vcpu_wake");
+            break;
+        case TRC_SCHED_YIELD:
+            if(opt.dump_all)
+                dump_sched_vcpu_action(ri, "vcpu_yield");
+            break;
+        case TRC_SCHED_BLOCK:
+            if(opt.dump_all)
+                dump_sched_vcpu_action(ri, "vcpu_block");
+            break;
+        case TRC_SCHED_SHUTDOWN:
+        case TRC_SCHED_SHUTDOWN_CODE:
+            if(opt.dump_all) {
+                struct {
+                    unsigned int domid, vcpuid, reason;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s %s d%uv%u, reason = %u\n", ri->dump_header,
+                       ri->event == TRC_SCHED_SHUTDOWN ? "sched_shutdown" :
+                       "sched_shutdown_code", r->domid, r->vcpuid, r->reason);
+            }
+            break;
+        case TRC_SCHED_ADJDOM:
+            if(opt.dump_all) {
+                struct {
+                    unsigned int domid;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s sched_adjust d%u\n", ri->dump_header, r->domid);
+            }
+            break;
+        case TRC_SCHED_SWITCH:
+            dump_sched_switch(ri);
+            break;
+        case TRC_SCHED_SWITCH_INFPREV:
+            if(opt.dump_all) {
+                struct {
+                    unsigned int domid, 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);
+            }
+            break;
+        case TRC_SCHED_SWITCH_INFNEXT:
+            if(opt.dump_all)
+            {
+                struct {
+                    unsigned int domid, rsince;
+                    int slice;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s sched_switch next d%u", ri->dump_header, r->domid);
+                if ( r->rsince != 0 )
+                    printf(", was runnable for %u.%uus, ", r->rsince / 1000,
+                           r->rsince % 1000);
+                if ( r->slice > 0 )
+                    printf("next slice %u.%uus\n", 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:
+        case TRC_SCHED_DOM_TIMER_FN:
+            break;
+        default:
             process_generic(&p->ri);
         }
+    } else {
+        UPDATE_VOLUME(p, sched_verbose, ri->size);
+        process_generic(&p->ri);
     }
 }

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 12/14] xenalyze: handle Credit1 scheduler events
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (10 preceding siblings ...)
  2016-02-05 18:35 ` [PATCH 11/14] xenalyze: handle scheduling events Dario Faggioli
@ 2016-02-05 18:35 ` Dario Faggioli
  2016-02-05 18:35 ` [PATCH 13/14] xenalyze: handle Credit2 " Dario Faggioli
  2016-02-05 18:35 ` [PATCH 14/14] xenalyze: handle RTDS " Dario Faggioli
  13 siblings, 0 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:35 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap, Wei Liu, Olaf Hering, Ian Jackson, Ian Campbell

so the trace will show properly decoded info,
rather than just a bunch of hex codes.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Ian Campbell <ian.campbell@citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 tools/xentrace/xenalyze.c |   57 +++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 57 insertions(+)

diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
index be698aa..885c4e4 100644
--- a/tools/xentrace/xenalyze.c
+++ b/tools/xentrace/xenalyze.c
@@ -7673,6 +7673,63 @@ void sched_process(struct pcpu_info *p)
         default:
             process_generic(&p->ri);
         }
+    } else if(ri->evt.sub == 2) {
+        /* TRC_SCHED_CLASS */
+        switch(ri->event)
+        {
+        /* CREDIT (TRC_CSCHED_xxx) */
+        case TRC_SCHED_CLASS_EVT(CSCHED, 1): /* SCHED_TASKLET */
+            if(opt.dump_all)
+                printf(" %s csched:sched_tasklet\n", ri->dump_header);
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED, 2): /* ACCOUNT_START */
+        case TRC_SCHED_CLASS_EVT(CSCHED, 3): /* ACCOUNT_STOP  */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int domid, vcpuid, actv_cnt;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched:acct_%s d%uv%u, active_vcpus %u\n",
+                       ri->dump_header,
+                       ri->event == TRC_SCHED_CLASS_EVT(CSCHED, 2) ?
+                       "start" : "stop",
+                       r->domid, r->vcpuid,
+                       r->actv_cnt);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED, 4): /* STOLEN_VCPU   */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int peer_cpu, domid, vcpuid;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched:stolen_vcpu d%uv%u from cpu %u\n",
+                       ri->dump_header, r->domid, r->vcpuid, r->peer_cpu);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED, 5): /* PICKED_CPU    */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int domid, vcpuid, cpu;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched:pick_cpu %u for d%uv%u\n",
+                       ri->dump_header, r->cpu, r->domid, r->vcpuid);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED, 6): /* TICKLE        */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int cpu;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched:runq_tickle, cpu %u\n",
+                       ri->dump_header, r->cpu);
+            }
+            break;
+        default:
+            process_generic(ri);
+        }
     } else {
         UPDATE_VOLUME(p, sched_verbose, ri->size);
         process_generic(&p->ri);

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 13/14] xenalyze: handle Credit2 scheduler events
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (11 preceding siblings ...)
  2016-02-05 18:35 ` [PATCH 12/14] xenalyze: handle Credit1 scheduler events Dario Faggioli
@ 2016-02-05 18:35 ` Dario Faggioli
  2016-02-05 18:35 ` [PATCH 14/14] xenalyze: handle RTDS " Dario Faggioli
  13 siblings, 0 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:35 UTC (permalink / raw)
  To: xen-devel; +Cc: George Dunlap, Wei Liu, Olaf Hering, Ian Jackson, Ian Campbell

so the trace will show properly decoded info,
rather than just a bunch of hex codes.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Ian Campbell <ian.campbell@citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 tools/xentrace/xenalyze.c |  101 +++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 101 insertions(+)

diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
index 885c4e4..00dbf7c 100644
--- a/tools/xentrace/xenalyze.c
+++ b/tools/xentrace/xenalyze.c
@@ -7727,6 +7727,107 @@ void sched_process(struct pcpu_info *p)
                        ri->dump_header, r->cpu);
             }
             break;
+        /* CREDIT 2 (TRC_CSCHED2_xxx) */
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 1): /* TICK              */
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 4): /* CREDIT_ADD        */
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 9): /* UPDATE_LOAD       */
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 2): /* RUNQ_POS          */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16, pos;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched2:runq_insert d%uv%u, position %u\n",
+                       ri->dump_header, r->domid, r->vcpuid, r->pos);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 3): /* CREDIT_BURN       */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16, credit;
+                    int delta;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched2:burn_credits d%uv%u, credit = %u, delta = %d\n",
+                       ri->dump_header, r->domid, r->vcpuid,
+                       r->credit, r->delta);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 5): /* TICKLE_CHECK      */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16;
+                    unsigned int credit;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched2:tickle_check d%uv%u, credit = %u\n",
+                       ri->dump_header, r->domid, r->vcpuid, r->credit);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 6): /* TICKLE            */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int cpu:16;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched2:runq_tickle cpu %u\n",
+                       ri->dump_header, r->cpu);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 7):  /* CREDIT_RESET     */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16;
+                    unsigned int credit_start, credit_end;
+                    unsigned int multiplier;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched2:reset_credits d%uv%u, "
+                       "credit_start = %u, credit_end = %u, mult = %u\n",
+                       ri->dump_header, r->domid, r->vcpuid,
+                       r->credit_start, r->credit_end, r->multiplier);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 8):  /* SCHED_TASKLET    */
+            if(opt.dump_all)
+                printf(" %s csched2:sched_tasklet\n", ri->dump_header);
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 10): /* RUNQ_ASSIGN      */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16;
+                    unsigned int rqi;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched2:runq_assign d%uv%u on rq# %u\n",
+                       ri->dump_header, r->domid, r->vcpuid, r->rqi);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 11): /* UPDATE_VCPU_LOAD */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16;
+                    unsigned int avgload;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched2:update_vcpu_load d%uv%u, avg_load = %u\n",
+                       ri->dump_header, r->domid, r->vcpuid, r->avgload);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(CSCHED2, 12): /* UPDATE_RUNQ_LOAD */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int rq_load:4, rq_avgload:28;
+                    unsigned int rq_id:4, b_avgload:28;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s csched2:update_rq_load rq# %u, load = %u, "
+                       "avgload = %u, b_avgload = %u\n",
+                       ri->dump_header, r->rq_id, r->rq_load,
+                       r->rq_avgload, r->b_avgload);
+            }
+            break;
         default:
             process_generic(ri);
         }

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* [PATCH 14/14] xenalyze: handle RTDS scheduler events
  2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
                   ` (12 preceding siblings ...)
  2016-02-05 18:35 ` [PATCH 13/14] xenalyze: handle Credit2 " Dario Faggioli
@ 2016-02-05 18:35 ` Dario Faggioli
  13 siblings, 0 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-05 18:35 UTC (permalink / raw)
  To: xen-devel
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Tianyang Chen,
	Ian Jackson, Meng Xu

so the trace will show properly decoded info,
rather than just a bunch of hex codes.

Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
---
Cc: George Dunlap <george.dunlap@eu.citrix.com>
Cc: Meng Xu <xumengpanda@gmail.com>
Cc: Tianyang Chen <tiche@seas.upenn.edu>
Cc: Ian Jackson <ian.jackson@eu.citrix.com>
Cc: Ian Campbell <ian.campbell@citrix.com>
Cc: Wei Liu <wei.liu2@citrix.com>
Cc: Olaf Hering <olaf@aepfle.de>
---
 tools/xentrace/xenalyze.c |   59 +++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 59 insertions(+)

diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
index 00dbf7c..103e8b2 100644
--- a/tools/xentrace/xenalyze.c
+++ b/tools/xentrace/xenalyze.c
@@ -7828,6 +7828,65 @@ void sched_process(struct pcpu_info *p)
                        r->rq_avgload, r->b_avgload);
             }
             break;
+        /* RTDS (TRC_RTDS_xxx) */
+        case TRC_SCHED_CLASS_EVT(RTDS, 1): /* TICKLE           */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int cpu:16;
+                } * r = (typeof(r))ri->d;
+
+                printf(" %s rtds:runq_tickle cpu %u\n",
+                       ri->dump_header, r->cpu);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(RTDS, 2): /* RUNQ_PICK        */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16;
+                    unsigned int cur_dl_lo, cur_dl_hi;
+                    unsigned int cur_bg_lo, cur_bg_hi;
+                } * r = (typeof(r))ri->d;
+                uint64_t dl = (((uint64_t)r->cur_dl_hi) << 32) + r->cur_dl_lo;
+                uint64_t bg = (((uint64_t)r->cur_bg_hi) << 32) + r->cur_bg_lo;
+
+                printf(" %s rtds:runq_pick d%uv%u, deadline = %"PRIu64", "
+                       "budget = %"PRIu64"\n", ri->dump_header,
+                       r->domid, r->vcpuid, dl, bg);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(RTDS, 3): /* BUDGET_BURN      */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16;
+                    unsigned int cur_bg_lo, cur_bg_hi;
+                    int delta;
+                } * r = (typeof(r))ri->d;
+                uint64_t bg = (((uint64_t)r->cur_bg_hi) << 32) + r->cur_bg_lo;
+
+                printf(" %s rtds:burn_budget d%uv%u, budget = %"PRIu64", "
+                       "delta = %d\n", ri->dump_header, r->domid,
+                       r->vcpuid, bg, r->delta);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(RTDS, 4): /* BUDGET_REPLENISH */
+            if(opt.dump_all) {
+                struct {
+                    unsigned int vcpuid:16, domid:16;
+                    unsigned int cur_dl_lo, cur_dl_hi;
+                    unsigned int cur_bg_lo, cur_bg_hi;
+                } * r = (typeof(r))ri->d;
+                uint64_t dl = (((uint64_t)r->cur_dl_hi) << 32) + r->cur_dl_lo;
+                uint64_t bg = (((uint64_t)r->cur_bg_hi) << 32) + r->cur_bg_lo;
+
+                printf(" %s rtds:repl_budget d%uv%u, deadline = %"PRIu64", "
+                       "budget = %"PRIu64"\n", ri->dump_header,
+                       r->domid, r->vcpuid, dl, bg);
+            }
+            break;
+        case TRC_SCHED_CLASS_EVT(RTDS, 5): /* SCHED_TASKLET    */
+            if(opt.dump_all)
+                printf(" %s rtds:sched_tasklet\n", ri->dump_header);
+            break;
         default:
             process_generic(ri);
         }

^ permalink raw reply related	[flat|nested] 31+ messages in thread

* Re: [PATCH 01/14] xen: sched: __runq_tickle takes a useless cpu parameter
  2016-02-05 18:33 ` [PATCH 01/14] xen: sched: __runq_tickle takes a useless cpu parameter Dario Faggioli
@ 2016-02-15 16:14   ` Konrad Rzeszutek Wilk
  2016-02-15 16:29     ` Dario Faggioli
  0 siblings, 1 reply; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:14 UTC (permalink / raw)
  To: Dario Faggioli; +Cc: xen-devel, George Dunlap

On Fri, Feb 05, 2016 at 07:33:34PM +0100, Dario Faggioli wrote:
> as it is always acts on v->processor of the vcpu because
> of which we are tickling.

s/because of which// ?

> 
> Getting rid of it makes the code easier to understand
> and better looking.
> 
> While there, remove a spurious blank line.
> 

Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>

> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> ---
> Cc: George Dunlap <george.dunlap@citrix.com>
> ---
>  xen/common/sched_credit.c |   10 ++++------
>  1 file changed, 4 insertions(+), 6 deletions(-)
> 
> diff --git a/xen/common/sched_credit.c b/xen/common/sched_credit.c
> index 671bbee..5279b92 100644
> --- a/xen/common/sched_credit.c
> +++ b/xen/common/sched_credit.c
> @@ -360,9 +360,9 @@ boolean_param("tickle_one_idle_cpu", opt_tickle_one_idle);
>  
>  DEFINE_PER_CPU(unsigned int, last_tickle_cpu);
>  
> -static inline void
> -__runq_tickle(unsigned int cpu, struct csched_vcpu *new)
> +static inline void __runq_tickle(struct csched_vcpu *new)
>  {
> +    unsigned int cpu = new->vcpu->processor;
>      struct csched_vcpu * const cur = CSCHED_VCPU(curr_on_cpu(cpu));
>      struct csched_private *prv = CSCHED_PRIV(per_cpu(scheduler, cpu));
>      cpumask_t mask, idle_mask, *online;
> @@ -375,7 +375,6 @@ __runq_tickle(unsigned int cpu, struct csched_vcpu *new)
>      cpumask_and(&idle_mask, prv->idlers, online);
>      idlers_empty = cpumask_empty(&idle_mask);
>  
> -
>      /*
>       * If the pcpu is idle, or there are no idlers and the new
>       * vcpu is a higher priority than the old vcpu, run it here.
> @@ -980,11 +979,10 @@ static void
>  csched_vcpu_wake(const struct scheduler *ops, struct vcpu *vc)
>  {
>      struct csched_vcpu * const svc = CSCHED_VCPU(vc);
> -    const unsigned int cpu = vc->processor;
>  
>      BUG_ON( is_idle_vcpu(vc) );
>  
> -    if ( unlikely(curr_on_cpu(cpu) == vc) )
> +    if ( unlikely(curr_on_cpu(vc->processor) == vc) )
>      {
>          SCHED_STAT_CRANK(vcpu_wake_running);
>          return;
> @@ -1028,7 +1026,7 @@ csched_vcpu_wake(const struct scheduler *ops, struct vcpu *vc)
>  
>      /* Put the VCPU on the runq and tickle CPUs */
>      __runq_insert(svc);
> -    __runq_tickle(cpu, svc);
> +    __runq_tickle(svc);
>  }
>  
>  static void
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 02/14] xen: sched: move up the trace record for vcpu_wake and vcpu_sleep
  2016-02-05 18:33 ` [PATCH 02/14] xen: sched: move up the trace record for vcpu_wake and vcpu_sleep Dario Faggioli
@ 2016-02-15 16:18   ` Konrad Rzeszutek Wilk
  0 siblings, 0 replies; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:18 UTC (permalink / raw)
  To: Dario Faggioli; +Cc: xen-devel, George Dunlap

On Fri, Feb 05, 2016 at 07:33:42PM +0100, Dario Faggioli wrote:
> vcpu_wake() and vcpu_sleep() are called before the specific
> schedulers wakeup and sleep routines (in fact, it is them
> that calls those specific routine).

Yeah!!

> 
> Make the trace reflect that, by moving the records up. In
> fact, it is more natural and easy to find the record of
> the event (e.g., the wakeup) *before* the records of the
> actions that deals with the event itself.
> 

Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> ---
> Cc: George Dunlap <george.dunlap@citrix.com>
> ---
>  xen/common/schedule.c |   16 ++++++++++------
>  1 file changed, 10 insertions(+), 6 deletions(-)
> 
> diff --git a/xen/common/schedule.c b/xen/common/schedule.c
> index 7306d71..c87922f 100644
> --- a/xen/common/schedule.c
> +++ b/xen/common/schedule.c
> @@ -381,7 +381,11 @@ void sched_destroy_domain(struct domain *d)
>  void vcpu_sleep_nosync(struct vcpu *v)
>  {
>      unsigned long flags;
> -    spinlock_t *lock = vcpu_schedule_lock_irqsave(v, &flags);
> +    spinlock_t *lock;
> +
> +    TRACE_2D(TRC_SCHED_SLEEP, v->domain->domain_id, v->vcpu_id);
> +
> +    lock = vcpu_schedule_lock_irqsave(v, &flags);
>  
>      if ( likely(!vcpu_runnable(v)) )
>      {
> @@ -392,8 +396,6 @@ void vcpu_sleep_nosync(struct vcpu *v)
>      }
>  
>      vcpu_schedule_unlock_irqrestore(lock, flags, v);
> -
> -    TRACE_2D(TRC_SCHED_SLEEP, v->domain->domain_id, v->vcpu_id);
>  }
>  
>  void vcpu_sleep_sync(struct vcpu *v)
> @@ -409,7 +411,11 @@ void vcpu_sleep_sync(struct vcpu *v)
>  void vcpu_wake(struct vcpu *v)
>  {
>      unsigned long flags;
> -    spinlock_t *lock = vcpu_schedule_lock_irqsave(v, &flags);
> +    spinlock_t *lock;
> +
> +    TRACE_2D(TRC_SCHED_WAKE, v->domain->domain_id, v->vcpu_id);
> +
> +    lock = vcpu_schedule_lock_irqsave(v, &flags);
>  
>      if ( likely(vcpu_runnable(v)) )
>      {
> @@ -424,8 +430,6 @@ void vcpu_wake(struct vcpu *v)
>      }
>  
>      vcpu_schedule_unlock_irqrestore(lock, flags, v);
> -
> -    TRACE_2D(TRC_SCHED_WAKE, v->domain->domain_id, v->vcpu_id);
>  }
>  
>  void vcpu_unblock(struct vcpu *v)
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 03/14] xen: sched: fi position of TRC_SCHED_DOM_{ADD, REM}
  2016-02-05 18:33 ` [PATCH 03/14] xen: sched: fi position of TRC_SCHED_DOM_{ADD, REM} Dario Faggioli
@ 2016-02-15 16:22   ` Konrad Rzeszutek Wilk
  2016-02-15 16:37     ` Dario Faggioli
  0 siblings, 1 reply; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:22 UTC (permalink / raw)
  To: Dario Faggioli; +Cc: George Dunlap, xen-devel

On Fri, Feb 05, 2016 at 07:33:50PM +0100, Dario Faggioli wrote:

On the title you have 'fi', but I think you meant 'fix'.

> so that they actually live in the functions that
> do the scheduling related domain initialization and
> destruction.
> 
> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>

.. would it make sense to have an overall high-level
'DOM_ADD' and 'DOM_REM' trace ?

Especially as it is useful for figuring out how long
an domain destruction takes time (based on the initial
trace to say this TRC_SCHED_REM)?

> ---
> Cc: George Dunlap <george.dunlap@eu.citrix.com>
> ---
>  xen/common/domain.c   |    1 -
>  xen/common/schedule.c |    4 ++--
>  2 files changed, 2 insertions(+), 3 deletions(-)
> 
> diff --git a/xen/common/domain.c b/xen/common/domain.c
> index 425767c..ddc7484 100644
> --- a/xen/common/domain.c
> +++ b/xen/common/domain.c
> @@ -867,7 +867,6 @@ void domain_destroy(struct domain *d)
>      cpupool_rm_domain(d);
>  
>      /* Delete from task list and task hashtable. */
> -    TRACE_1D(TRC_SCHED_DOM_REM, d->domain_id);
>      spin_lock(&domlist_update_lock);
>      pd = &domain_list;
>      while ( *pd != d ) 
> diff --git a/xen/common/schedule.c b/xen/common/schedule.c
> index c87922f..27695e3 100644
> --- a/xen/common/schedule.c
> +++ b/xen/common/schedule.c
> @@ -241,8 +241,6 @@ int sched_init_vcpu(struct vcpu *v, unsigned int processor)
>      if ( v->sched_priv == NULL )
>          return 1;
>  
> -    TRACE_2D(TRC_SCHED_DOM_ADD, v->domain->domain_id, v->vcpu_id);
> -
>      /* Idle VCPUs are scheduled immediately, so don't put them in runqueue. */
>      if ( is_idle_domain(d) )
>      {
> @@ -369,12 +367,14 @@ void sched_destroy_vcpu(struct vcpu *v)
>  int sched_init_domain(struct domain *d)
>  {
>      SCHED_STAT_CRANK(dom_init);
> +    TRACE_1D(TRC_SCHED_DOM_ADD, d->domain_id);
>      return SCHED_OP(DOM2OP(d), init_domain, d);
>  }
>  
>  void sched_destroy_domain(struct domain *d)
>  {
>      SCHED_STAT_CRANK(dom_destroy);
> +    TRACE_1D(TRC_SCHED_DOM_REM, d->domain_id);
>      SCHED_OP(DOM2OP(d), destroy_domain, d);
>  }
>  
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 04/14] xen: credit2: pack trace data better for xentrace_format
  2016-02-05 18:33 ` [PATCH 04/14] xen: credit2: pack trace data better for xentrace_format Dario Faggioli
@ 2016-02-15 16:29   ` Konrad Rzeszutek Wilk
  0 siblings, 0 replies; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:29 UTC (permalink / raw)
  To: Dario Faggioli; +Cc: xen-devel, Olaf Hering, George Dunlap

On Fri, Feb 05, 2016 at 07:33:57PM +0100, Dario Faggioli wrote:
> when tracing runstate changes, the vcpu and domain IDs
> are encoded in the lower and higher, respectively, parts
> of a 32 bits integer. When decoding a trace with
> xentrace_format, this makes it possible to display
> such events like this:
> 
> CPU0  833435853624 (+     768)  running_to_runnable [ dom:vcpu = 0x7fff0000 ]
> CPU0  833435854416 (+     792)  runnable_to_running [ dom:vcpu = 0x00000007 ]
> 
> For consistency, we should do the same when displaying
> the events coming from the Credit2 scheduler (when using
> the same tool), and to do that, we need to invert the
> order in which the fields are being put in the trace
> struct right now.
> 

Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>

> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> ---
> Cc: George Dunlap <george.dunlap@citrix.com>
> Cc: Olaf Hering <olaf@aepfle.de>
> ---
>  xen/common/sched_credit2.c |   16 ++++++++--------
>  1 file changed, 8 insertions(+), 8 deletions(-)
> 
> diff --git a/xen/common/sched_credit2.c b/xen/common/sched_credit2.c
> index 78220a7..cf40f68 100644
> --- a/xen/common/sched_credit2.c
> +++ b/xen/common/sched_credit2.c
> @@ -382,7 +382,7 @@ __update_svc_load(const struct scheduler *ops,
>  
>      {
>          struct {
> -            unsigned dom:16,vcpu:16;
> +            unsigned vcpu:16, dom:16;
>              unsigned v_avgload:32;
>          } d;
>          d.dom = svc->vcpu->domain->domain_id;
> @@ -450,7 +450,7 @@ runq_insert(const struct scheduler *ops, unsigned int cpu, struct csched2_vcpu *
>  
>      {
>          struct {
> -            unsigned dom:16,vcpu:16;
> +            unsigned vcpu:16, dom:16;
>              unsigned pos;
>          } d;
>          d.dom = svc->vcpu->domain->domain_id;
> @@ -536,7 +536,7 @@ runq_tickle(const struct scheduler *ops, unsigned int cpu, struct csched2_vcpu *
>  
>          /* TRACE */ {
>              struct {
> -                unsigned dom:16,vcpu:16;
> +                unsigned vcpu:16, dom:16;
>                  unsigned credit;
>              } d;
>              d.dom = cur->vcpu->domain->domain_id;
> @@ -561,9 +561,9 @@ tickle:
>  
>      /* TRACE */ {
>          struct {
> -            unsigned cpu:8;
> +            unsigned cpu:16, pad:16;
>          } d;
> -        d.cpu = ipid;
> +        d.cpu = ipid; d.pad = 0;
>          trace_var(TRC_CSCHED2_TICKLE, 0,
>                    sizeof(d),
>                    (unsigned char *)&d);
> @@ -634,7 +634,7 @@ static void reset_credit(const struct scheduler *ops, int cpu, s_time_t now,
>  
>          /* TRACE */ {
>              struct {
> -                unsigned dom:16,vcpu:16;
> +                unsigned vcpu:16, dom:16;
>                  unsigned credit_start, credit_end;
>                  unsigned multiplier;
>              } d;
> @@ -683,7 +683,7 @@ void burn_credits(struct csched2_runqueue_data *rqd, struct csched2_vcpu *svc, s
>      /* TRACE */
>      {
>          struct {
> -            unsigned dom:16,vcpu:16;
> +            unsigned vcpu:16, dom:16;
>              unsigned credit;
>              int delta;
>          } d;
> @@ -812,7 +812,7 @@ __runq_assign(struct csched2_vcpu *svc, struct csched2_runqueue_data *rqd)
>      /* TRACE */
>      {
>          struct {
> -            unsigned dom:16,vcpu:16;
> +            unsigned vcpu:16, dom:16;
>              unsigned rqi:16;
>          } d;
>          d.dom = svc->vcpu->domain->domain_id;
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 01/14] xen: sched: __runq_tickle takes a useless cpu parameter
  2016-02-15 16:14   ` Konrad Rzeszutek Wilk
@ 2016-02-15 16:29     ` Dario Faggioli
  0 siblings, 0 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-15 16:29 UTC (permalink / raw)
  To: Konrad Rzeszutek Wilk; +Cc: xen-devel, George Dunlap


[-- Attachment #1.1: Type: text/plain, Size: 867 bytes --]

On Mon, 2016-02-15 at 11:14 -0500, Konrad Rzeszutek Wilk wrote:
> On Fri, Feb 05, 2016 at 07:33:34PM +0100, Dario Faggioli wrote:
> > as it is always acts on v->processor of the vcpu because
> > of which we are tickling.
> 
> s/because of which// ?
> 
Yeah, well, technically, as tickling means "raising the
SCHEDULE_SOFTIRQ on a pcpu", I tend to see and describe it as "we
tickled pcpu X because of vcpu k woke up".

But this may well be me, and I'm fine both keeping or killing that
"because of which".

> Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
> 
Thanks,
Dario

-- 
<<This happens because I choose it to happen!>> (Raistlin Majere)
-----------------------------------------------------------------
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK)


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 05/14] xen: RTDS: pack trace data better for xentrace_format
  2016-02-05 18:34 ` [PATCH 05/14] xen: RTDS: " Dario Faggioli
@ 2016-02-15 16:31   ` Konrad Rzeszutek Wilk
  0 siblings, 0 replies; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:31 UTC (permalink / raw)
  To: Dario Faggioli
  Cc: xen-devel, Olaf Hering, Tianyang Chen, Meng Xu, George Dunlap

On Fri, Feb 05, 2016 at 07:34:05PM +0100, Dario Faggioli wrote:
> when tracing runstate changes, the vcpu and domain IDs
> are encoded in the lower and higher, respectively, parts
> of a 32 bits integer. When decoding a trace with
> xentrace_format, this makes it possible to display
> such events like this:
> 
> CPU0  833435853624 (+     768)  running_to_runnable [ dom:vcpu = 0x7fff0000 ]
> CPU0  833435854416 (+     792)  runnable_to_running [ dom:vcpu = 0x00000007 ]
> 
> For consistency, we should do the same when displaying
> the events coming from the RTDS scheduler (when using
> the same tool), and to do that, we need to invert the
> order in which the fields are being put in the trace
> struct right now.
> 
> While there, we also:
>  - fix the use of TRC_RTDS_SCHED_TASKLET (it should
>    only be involved when a tasklet is scheduled, not
>    _every_ time rt_schedule() is invoked!);
>  - remove a very chatty and useless (nothing has been
>    picked!) use of TRC_RTDS_RUNQ_PICK.
> 

I would add: "One can observe the case where nothing has been
picked by looking at when the cpu_idle is invoked - which is
the same mechanism on credit1,2 where we can see if the
scheduler hadn't picked anything from the runqueue."


Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>

> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> ---
> Cc: George Dunlap <george.dunlap@citrix.com>
> Cc: Meng Xu <xumengpanda@gmail.com>
> Cc: Tianyang Chen <tiche@seas.upenn.edu>
> Cc: Olaf Hering <olaf@aepfle.de>
> ---
>  xen/common/sched_rt.c |   27 ++++-----------------------
>  1 file changed, 4 insertions(+), 23 deletions(-)
> 
> diff --git a/xen/common/sched_rt.c b/xen/common/sched_rt.c
> index 2e5430f..53de6d6 100644
> --- a/xen/common/sched_rt.c
> +++ b/xen/common/sched_rt.c
> @@ -362,7 +362,7 @@ rt_update_deadline(s_time_t now, struct rt_vcpu *svc)
>      /* TRACE */
>      {
>          struct {
> -            unsigned dom:16,vcpu:16;
> +            unsigned vcpu:16, dom:16;
>              unsigned cur_deadline_lo, cur_deadline_hi;
>              unsigned cur_budget_lo, cur_budget_hi;
>          } d;
> @@ -711,7 +711,7 @@ burn_budget(const struct scheduler *ops, struct rt_vcpu *svc, s_time_t now)
>      /* TRACE */
>      {
>          struct {
> -            unsigned dom:16, vcpu:16;
> +            unsigned vcpu:16, dom:16;
>              unsigned cur_budget_lo;
>              unsigned cur_budget_hi;
>              int delta;
> @@ -763,7 +763,7 @@ __runq_pick(const struct scheduler *ops, const cpumask_t *mask)
>          if( svc != NULL )
>          {
>              struct {
> -                unsigned dom:16, vcpu:16;
> +                unsigned vcpu:16, dom:16;
>                  unsigned cur_deadline_lo, cur_deadline_hi;
>                  unsigned cur_budget_lo, cur_budget_hi;
>              } d;
> @@ -777,8 +777,6 @@ __runq_pick(const struct scheduler *ops, const cpumask_t *mask)
>                        sizeof(d),
>                        (unsigned char *) &d);
>          }
> -        else
> -            trace_var(TRC_RTDS_RUNQ_PICK, 1, 0, NULL);
>      }
>  
>      return svc;
> @@ -845,6 +843,7 @@ rt_schedule(const struct scheduler *ops, s_time_t now, bool_t tasklet_work_sched
>  
>      if ( tasklet_work_scheduled )
>      {
> +        trace_var(TRC_RTDS_SCHED_TASKLET, 1, 0,  NULL);
>          snext = rt_vcpu(idle_vcpu[cpu]);
>      }
>      else
> @@ -885,24 +884,6 @@ rt_schedule(const struct scheduler *ops, s_time_t now, bool_t tasklet_work_sched
>      ret.time = MIN(snext->budget, MAX_SCHEDULE); /* sched quantum */
>      ret.task = snext->vcpu;
>  
> -    /* TRACE */
> -    {
> -        struct {
> -            unsigned dom:16,vcpu:16;
> -            unsigned cur_deadline_lo, cur_deadline_hi;
> -            unsigned cur_budget_lo, cur_budget_hi;
> -        } d;
> -        d.dom = snext->vcpu->domain->domain_id;
> -        d.vcpu = snext->vcpu->vcpu_id;
> -        d.cur_deadline_lo = (unsigned) snext->cur_deadline;
> -        d.cur_deadline_hi = (unsigned) (snext->cur_deadline >> 32);
> -        d.cur_budget_lo = (unsigned) snext->cur_budget;
> -        d.cur_budget_hi = (unsigned) (snext->cur_budget >> 32);
> -        trace_var(TRC_RTDS_SCHED_TASKLET, 1,
> -                  sizeof(d),
> -                  (unsigned char *)&d);
> -    }
> -
>      return ret;
>  }
>  
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 06/14] xen: sched: tracing: enable TSC tracing for all events
  2016-02-05 18:34 ` [PATCH 06/14] xen: sched: tracing: enable TSC tracing for all events Dario Faggioli
@ 2016-02-15 16:32   ` Konrad Rzeszutek Wilk
  2016-02-15 17:00     ` Dario Faggioli
  0 siblings, 1 reply; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:32 UTC (permalink / raw)
  To: Dario Faggioli
  Cc: xen-devel, Olaf Hering, Tianyang Chen, Meng Xu, George Dunlap

On Fri, Feb 05, 2016 at 07:34:18PM +0100, Dario Faggioli wrote:
> it is enabled for pretty much all of them already.
> There were just a few that had it disabled.
> 
> When tracing a scheduler, timing information is
> really important, so enable it everywhere scheduling
> related.
> 
> Note that this was not really a problem if looking
> at the traces with xenalyze, but it was if using
> xentrace_format.

Was there any historical reason it was not used?

> 
> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> ---
> Cc: George Dunlap <george.dunlap@citrix.com>
> Cc: Meng Xu <xumengpanda@gmail.com>
> Cc: Tianyang Chen <tiche@seas.upenn.edu>
> Cc: Olaf Hering <olaf@aepfle.de>
> ---
>  xen/common/sched_credit.c  |    2 +-
>  xen/common/sched_credit2.c |    6 +++---
>  xen/common/sched_rt.c      |    2 +-
>  3 files changed, 5 insertions(+), 5 deletions(-)
> 
> diff --git a/xen/common/sched_credit.c b/xen/common/sched_credit.c
> index 5279b92..bd2f37f 100644
> --- a/xen/common/sched_credit.c
> +++ b/xen/common/sched_credit.c
> @@ -476,7 +476,7 @@ static inline void __runq_tickle(struct csched_vcpu *new)
>          {
>              /* Avoid TRACE_*: saves checking !tb_init_done each step */
>              for_each_cpu(cpu, &mask)
> -                __trace_var(TRC_CSCHED_TICKLE, 0, sizeof(cpu), &cpu);
> +                __trace_var(TRC_CSCHED_TICKLE, 1, sizeof(cpu), &cpu);
>          }
>  
>          /* Send scheduler interrupts to designated CPUs */
> diff --git a/xen/common/sched_credit2.c b/xen/common/sched_credit2.c
> index cf40f68..2934e26 100644
> --- a/xen/common/sched_credit2.c
> +++ b/xen/common/sched_credit2.c
> @@ -456,7 +456,7 @@ runq_insert(const struct scheduler *ops, unsigned int cpu, struct csched2_vcpu *
>          d.dom = svc->vcpu->domain->domain_id;
>          d.vcpu = svc->vcpu->vcpu_id;
>          d.pos = pos;
> -        trace_var(TRC_CSCHED2_RUNQ_POS, 0,
> +        trace_var(TRC_CSCHED2_RUNQ_POS, 1,
>                    sizeof(d),
>                    (unsigned char *)&d);
>      }
> @@ -564,7 +564,7 @@ tickle:
>              unsigned cpu:16, pad:16;
>          } d;
>          d.cpu = ipid; d.pad = 0;
> -        trace_var(TRC_CSCHED2_TICKLE, 0,
> +        trace_var(TRC_CSCHED2_TICKLE, 1,
>                    sizeof(d),
>                    (unsigned char *)&d);
>      }
> @@ -1721,7 +1721,7 @@ csched2_schedule(
>       */
>      if ( tasklet_work_scheduled )
>      {
> -        trace_var(TRC_CSCHED2_SCHED_TASKLET, 0, 0,  NULL);
> +        trace_var(TRC_CSCHED2_SCHED_TASKLET, 1, 0,  NULL);
>          snext = CSCHED2_VCPU(idle_vcpu[cpu]);
>      }
>      else
> diff --git a/xen/common/sched_rt.c b/xen/common/sched_rt.c
> index 53de6d6..33ac9de 100644
> --- a/xen/common/sched_rt.c
> +++ b/xen/common/sched_rt.c
> @@ -985,7 +985,7 @@ out:
>          } d;
>          d.cpu = cpu_to_tickle;
>          d.pad = 0;
> -        trace_var(TRC_RTDS_TICKLE, 0,
> +        trace_var(TRC_RTDS_TICKLE, 1,
>                    sizeof(d),
>                    (unsigned char *)&d);
>      }
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 03/14] xen: sched: fi position of TRC_SCHED_DOM_{ADD, REM}
  2016-02-15 16:22   ` Konrad Rzeszutek Wilk
@ 2016-02-15 16:37     ` Dario Faggioli
  2016-02-15 16:41       ` Konrad Rzeszutek Wilk
  0 siblings, 1 reply; 31+ messages in thread
From: Dario Faggioli @ 2016-02-15 16:37 UTC (permalink / raw)
  To: Konrad Rzeszutek Wilk; +Cc: George Dunlap, xen-devel


[-- Attachment #1.1: Type: text/plain, Size: 1677 bytes --]

On Mon, 2016-02-15 at 11:22 -0500, Konrad Rzeszutek Wilk wrote:
> On Fri, Feb 05, 2016 at 07:33:50PM +0100, Dario Faggioli wrote:
> 
> On the title you have 'fi', but I think you meant 'fix'.
> 
Indeed, sorry for that.

> > so that they actually live in the functions that
> > do the scheduling related domain initialization and
> > destruction.
> > 
> > Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> 
> .. would it make sense to have an overall high-level
> 'DOM_ADD' and 'DOM_REM' trace ?
> 
> Especially as it is useful for figuring out how long
> an domain destruction takes time (based on the initial
> trace to say this TRC_SCHED_REM)?
> 
I think it makes sense, and I can either do this in this patch (and
resend) or as a follow up.

I guess the only possible concern is that we may introduce too much
tracing, to the point that it hurts performance, even when not enabled.
(I was starting to think about this anyway, as I've got other series,
either posted or in my queues, that adds a few more tracepoints,
because they're so damn useful! ;-P)

In that case, I guess we could think of doing something similar to what
ftrace does in Linux --for disabling and enabling tracing and
tracepoints-- which should be more lightweight than what we do.

In any case, none of this applies to a "DOM_ADD" / "DOM_REM" tracing
events. :-)

Thanks and Regards,
Dario

-- 
<<This happens because I choose it to happen!>> (Raistlin Majere)
-----------------------------------------------------------------
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK)


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 07/14] xentrace: formats: update format of scheduling events
  2016-02-05 18:34 ` [PATCH 07/14] xentrace: formats: update format of scheduling events Dario Faggioli
@ 2016-02-15 16:38   ` Konrad Rzeszutek Wilk
  2016-02-15 16:42     ` Dario Faggioli
  0 siblings, 1 reply; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:38 UTC (permalink / raw)
  To: Dario Faggioli
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Ian Jackson,
	xen-devel

On Fri, Feb 05, 2016 at 07:34:30PM +0100, Dario Faggioli wrote:
> to include the vcpu IDs, in a way that matches
> how the "dom:vcpu" couple is displayed in other
> events (runstate changes).

Could you also add:
"Also add the trace for TRC_SCHED_SHUTDOWN_CODE which
was missing and was done via SCHEDOP_shutdown_code hypercall.
(TRC_SCHED_SHUTDOWN trace was present)."

Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>

> 
> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> ---
> Cc: George Dunlap <george.dunlap@eu.citrix.com>
> Cc: Ian Jackson <ian.jackson@eu.citrix.com>
> Cc: Ian Campbell <ian.campbell@citrix.com>
> Cc: Wei Liu <wei.liu2@citrix.com>
> Cc: Olaf Hering <olaf@aepfle.de>
> ---
>  tools/xentrace/formats |   18 +++++++++---------
>  1 file changed, 9 insertions(+), 9 deletions(-)
> 
> diff --git a/tools/xentrace/formats b/tools/xentrace/formats
> index 5d7b72a..5257cf0 100644
> --- a/tools/xentrace/formats
> +++ b/tools/xentrace/formats
> @@ -19,22 +19,22 @@
>  0x00021311  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  offline_to_runnable [ dom:vcpu = 0x%(1)08x ]
>  0x00021321  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  offline_to_blocked  [ dom:vcpu = 0x%(1)08x ]
>  
> -0x00028001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_add_domain  [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
> -0x00028002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_rem_domain  [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
> -0x00028003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_sleep      [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
> -0x00028004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_wake       [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
> -0x00028005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_yield          [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
> -0x00028006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_block          [ domid = 0x%(1)08x, edomid = 0x%(2)08x ]
> -0x00022006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_block          [ dom:vcpu = 0x%(1)08x, domid = 0x%(2)08x ]
> -0x00028007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown	  [ domid = 0x%(1)08x, edomid = 0x%(2)08x, reason = 0x%(3)08x ]
> +0x00028001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_add_domain  [ domid = 0x%(1)08x ]
> +0x00028002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_rem_domain  [ domid = 0x%(1)08x ]
> +0x00028003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_sleep      [ dom:vcpu = 0x%(1)04x%(2)04x ]
> +0x00028004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_wake       [ dom:vcpu = 0x%(1)04x%(2)04x ]
> +0x00028005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_yield          [ dom:vcpu = 0x%(1)04x%(2)04x ]
> +0x00028006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  do_block          [ dom:vcpu = 0x%(1)04x%(2)04x ]
> +0x00028007  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown	  [ dom:vcpu = 0x%(1)04x%(2)04x, reason = 0x%(3)08x ]
>  0x00028008  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_ctl
>  0x00028009  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  sched_adjdom      [ domid = 0x%(1)08x ]
> -0x0002800a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  __enter_scheduler [ prev<domid:edomid> = 0x%(1)08x : 0x%(2)08x, next<domid:edomid> = 0x%(3)08x : 0x%(4)08x ]
> +0x0002800a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  __enter_scheduler [ prev<dom:vcpu> = 0x%(1)04x%(2)04x, next<dom:vcpu> = 0x%(3)04x%(4)04x ]
>  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 ]
> +0x00028010  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  domain_shutdown_code [ dom:vcpu = 0x%(1)04x%(2)04x, reason = 0x%(3)08x ]
>  
>  0x00081001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMENTRY
>  0x00081002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(2)08x ]
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 08/14] xentrace: formats: add events from Credit scheduler
  2016-02-05 18:34 ` [PATCH 08/14] xentrace: formats: add events from Credit scheduler Dario Faggioli
@ 2016-02-15 16:40   ` Konrad Rzeszutek Wilk
  0 siblings, 0 replies; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:40 UTC (permalink / raw)
  To: Dario Faggioli
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Ian Jackson,
	xen-devel

On Fri, Feb 05, 2016 at 07:34:43PM +0100, Dario Faggioli wrote:
> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>

Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
> ---
> Cc: George Dunlap <george.dunlap@eu.citrix.com>
> Cc: Ian Jackson <ian.jackson@eu.citrix.com>
> Cc: Ian Campbell <ian.campbell@citrix.com>
> Cc: Wei Liu <wei.liu2@citrix.com>
> Cc: Olaf Hering <olaf@aepfle.de>
> ---
>  tools/xentrace/formats |    7 +++++++
>  1 file changed, 7 insertions(+)
> 
> diff --git a/tools/xentrace/formats b/tools/xentrace/formats
> index 5257cf0..a5636e9 100644
> --- a/tools/xentrace/formats
> +++ b/tools/xentrace/formats
> @@ -36,6 +36,13 @@
>  0x0002800f  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  switch_infnext    [ new_domid = 0x%(1)08x, time = %(2)d, r_time = %(3)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
> +0x00022002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:account_start [ dom:vcpu = 0x%(1)04x%(2)04x, active = %(3)d ]
> +0x00022003  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:account_stop  [ dom:vcpu = 0x%(1)04x%(2)04x, active = %(3)d ]
> +0x00022004  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:stolen_vcpu   [ dom:vcpu = 0x%(2)04x%(3)04x, from = %(1)d ]
> +0x00022005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:picked_cpu    [ dom:vcpu = 0x%(1)04x%(2)04x, cpu = %(3)d ]
> +0x00022006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:tickle        [ cpu = %(1)d ]
> +
>  0x00081001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMENTRY
>  0x00081002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(2)08x ]
>  0x00081102  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(3)08x%(2)08x ]
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 03/14] xen: sched: fi position of TRC_SCHED_DOM_{ADD, REM}
  2016-02-15 16:37     ` Dario Faggioli
@ 2016-02-15 16:41       ` Konrad Rzeszutek Wilk
  0 siblings, 0 replies; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:41 UTC (permalink / raw)
  To: Dario Faggioli; +Cc: George Dunlap, xen-devel

On Mon, Feb 15, 2016 at 05:37:05PM +0100, Dario Faggioli wrote:
> On Mon, 2016-02-15 at 11:22 -0500, Konrad Rzeszutek Wilk wrote:
> > On Fri, Feb 05, 2016 at 07:33:50PM +0100, Dario Faggioli wrote:
> > 
> > On the title you have 'fi', but I think you meant 'fix'.
> > 
> Indeed, sorry for that.
> 
> > > so that they actually live in the functions that
> > > do the scheduling related domain initialization and
> > > destruction.
> > > 
> > > Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> > 
> > .. would it make sense to have an overall high-level
> > 'DOM_ADD' and 'DOM_REM' trace ?
> > 
> > Especially as it is useful for figuring out how long
> > an domain destruction takes time (based on the initial
> > trace to say this TRC_SCHED_REM)?
> > 
> I think it makes sense, and I can either do this in this patch (and
> resend) or as a follow up.
> 
> I guess the only possible concern is that we may introduce too much
> tracing, to the point that it hurts performance, even when not enabled.

.. How often do we do these operations?

> (I was starting to think about this anyway, as I've got other series,
> either posted or in my queues, that adds a few more tracepoints,
> because they're so damn useful! ;-P)
> 
> In that case, I guess we could think of doing something similar to what
> ftrace does in Linux --for disabling and enabling tracing and
> tracepoints-- which should be more lightweight than what we do.
> 
> In any case, none of this applies to a "DOM_ADD" / "DOM_REM" tracing
> events. :-)

Correct. This patch does fix the mis-use of the trace points.
> 
> Thanks and Regards,
> Dario
> 
> -- 
> <<This happens because I choose it to happen!>> (Raistlin Majere)
> -----------------------------------------------------------------
> Dario Faggioli, Ph.D, http://about.me/dario.faggioli
> Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK)
> 

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 07/14] xentrace: formats: update format of scheduling events
  2016-02-15 16:38   ` Konrad Rzeszutek Wilk
@ 2016-02-15 16:42     ` Dario Faggioli
  0 siblings, 0 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-15 16:42 UTC (permalink / raw)
  To: Konrad Rzeszutek Wilk
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Ian Jackson,
	xen-devel


[-- Attachment #1.1: Type: text/plain, Size: 833 bytes --]

On Mon, 2016-02-15 at 11:38 -0500, Konrad Rzeszutek Wilk wrote:
> On Fri, Feb 05, 2016 at 07:34:30PM +0100, Dario Faggioli wrote:
> > to include the vcpu IDs, in a way that matches
> > how the "dom:vcpu" couple is displayed in other
> > events (runstate changes).
> 
> Could you also add:
> "Also add the trace for TRC_SCHED_SHUTDOWN_CODE which
> was missing and was done via SCHEDOP_shutdown_code hypercall.
> (TRC_SCHED_SHUTDOWN trace was present)."
> 
Yep, sure I can.

> Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
> 
Thanks,
Dario

-- 
<<This happens because I choose it to happen!>> (Raistlin Majere)
-----------------------------------------------------------------
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK)


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 09/14] xentrace: formats: add events from Credit2 scheduler
  2016-02-05 18:34 ` [PATCH 09/14] xentrace: formats: add events from Credit2 scheduler Dario Faggioli
@ 2016-02-15 16:44   ` Konrad Rzeszutek Wilk
  0 siblings, 0 replies; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:44 UTC (permalink / raw)
  To: Dario Faggioli
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Ian Jackson,
	xen-devel

On Fri, Feb 05, 2016 at 07:34:56PM +0100, Dario Faggioli wrote:
> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> ---
> Cc: George Dunlap <george.dunlap@eu.citrix.com>
> Cc: Ian Jackson <ian.jackson@eu.citrix.com>
> Cc: Ian Campbell <ian.campbell@citrix.com>
> Cc: Wei Liu <wei.liu2@citrix.com>
> Cc: Olaf Hering <olaf@aepfle.de>
> ---
>  tools/xentrace/formats |   13 +++++++++++++
>  1 file changed, 13 insertions(+)
> 
> diff --git a/tools/xentrace/formats b/tools/xentrace/formats
> index a5636e9..b8ec06b 100644
> --- a/tools/xentrace/formats
> +++ b/tools/xentrace/formats
> @@ -43,6 +43,19 @@
>  0x00022005  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:picked_cpu    [ dom:vcpu = 0x%(1)04x%(2)04x, cpu = %(3)d ]
>  0x00022006  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched:tickle        [ cpu = %(1)d ]
>  
> +0x00022201  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:tick
> +0x00022202  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:runq_pos       [ dom:vcpu = 0x%(1)08x, pos = %(2)d]
> +0x00022203  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:credit burn    [ dom:vcpu = 0x%(1)08x, credit = %(2)d, delta = %(3)d ]
> +0x00022204  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:credit_add
> +0x00022205  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:tickle_check   [ dom:vcpu = 0x%(1)08x, credit = %(2)d ]
> +0x00022206  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:tickle         [ cpu = %(1)d ]
> +0x00022207  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:credit_reset   [ dom:vcpu = 0x%(1)08x, cr_start = %(2)d, cr_end = %(3)d, mult = %(4)d ]
> +0x00022208  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:sched_tasklet
> +0x00022209  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:update_load
> +0x0002220a  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:runq_assign    [ dom:vcpu = 0x%(1)08x, rq_idx = %(2)d ]
> +0x0002220b  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:updt_vcpu_load [ dom:vcpu = 0x%(1)08x, avgload = %(2)d ]
> +0x0002220c  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  csched2:updt_runq_load [ rq_load[4]:rq_avgload[28] = 0x%(1)08x, rq_idx[4]:b_avgload[28] = 0x%(2)08x ]
> +

s/rq_idx/rq_id/

>  0x00081001  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMENTRY
>  0x00081002  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(2)08x ]
>  0x00081102  CPU%(cpu)d  %(tsc)d (+%(reltsc)8d)  VMEXIT      [ exitcode = 0x%(1)08x, rIP  = 0x%(3)08x%(2)08x ]
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 11/14] xenalyze: handle scheduling events
  2016-02-05 18:35 ` [PATCH 11/14] xenalyze: handle scheduling events Dario Faggioli
@ 2016-02-15 16:51   ` Konrad Rzeszutek Wilk
  2016-02-15 17:03     ` Dario Faggioli
  0 siblings, 1 reply; 31+ messages in thread
From: Konrad Rzeszutek Wilk @ 2016-02-15 16:51 UTC (permalink / raw)
  To: Dario Faggioli
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Ian Jackson,
	xen-devel

On Fri, Feb 05, 2016 at 07:35:22PM +0100, Dario Faggioli wrote:
> so the trace will show properly decoded info,
> rather than just a bunch of hex codes.
> 
> Signed-off-by: Dario Faggioli <dario.faggioli@citrix.com>
> ---
> Cc: George Dunlap <george.dunlap@eu.citrix.com>
> Cc: Ian Jackson <ian.jackson@eu.citrix.com>
> Cc: Ian Campbell <ian.campbell@citrix.com>
> Cc: Wei Liu <wei.liu2@citrix.com>
> Cc: Olaf Hering <olaf@aepfle.de>
> ---
>  tools/xentrace/xenalyze.c |  156 ++++++++++++++++++++++++++++++++++++---------
>  1 file changed, 126 insertions(+), 30 deletions(-)
> 
> diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
> index 6520790..be698aa 100644
> --- a/tools/xentrace/xenalyze.c
> +++ b/tools/xentrace/xenalyze.c
> @@ -1519,27 +1519,6 @@ struct pv_data {
>  };
>  
>  /* Sched data */
> -
> -enum {
> -    SCHED_DOM_ADD=1,
> -    SCHED_DOM_REM,
> -    SCHED_SLEEP,
> -    SCHED_WAKE,
> -    SCHED_YIELD,
> -    SCHED_BLOCK,
> -    SCHED_SHUTDOWN,
> -    SCHED_CTL,
> -    SCHED_ADJDOM,
> -    SCHED_SWITCH,
> -    SCHED_S_TIMER_FN,
> -    SCHED_T_TIMER_FN,
> -    SCHED_DOM_TIMER_FN,
> -    SCHED_SWITCH_INFPREV,
> -    SCHED_SWITCH_INFNEXT,
> -    SCHED_SHUTDOWN_CODE,
> -    SCHED_MAX
> -};
> -
>  enum {
>      RUNSTATE_RUNNING=0,
>      RUNSTATE_RUNNABLE,
> @@ -7431,6 +7410,17 @@ no_update:
>      return;
>  }
>  
> +void dump_sched_switch(struct record_info *ri)
> +{
> +    struct {
> +        unsigned int prev_dom, prev_vcpu, next_dom, next_vcpu;
> +    } * r = (typeof(r))ri->d;
> +
> +    printf(" %s sched_switch prev d%uv%u next d%uv%u\n",
> +           ri->dump_header, r->prev_dom, r->prev_vcpu,
> +           r->next_dom, r->next_vcpu);
> +}
> +
>  void sched_switch_process(struct pcpu_info *p)
>  {
>      struct vcpu_data *prev, *next;
> @@ -7440,10 +7430,7 @@ void sched_switch_process(struct pcpu_info *p)
>      } * r = (typeof(r))ri->d;
>  
>      if(opt.dump_all)
> -        printf("%s sched_switch prev d%uv%u next d%uv%u\n",
> -               ri->dump_header,
> -               r->prev_dom, r->prev_vcpu,
> -               r->next_dom, r->next_vcpu);
> +        dump_sched_switch(ri);
>  
>      if(r->prev_vcpu > MAX_CPUS)
>      {
> @@ -7559,6 +7546,14 @@ void sched_summary_domain(struct domain_data *d)
>      }
>  }
>  
> +void dump_sched_vcpu_action(struct record_info *ri, const char *action)
> +{
> +    struct {
> +        unsigned int domid, vcpuid;
> +    } * r = (typeof(r))ri->d;
> +
> +    printf(" %s %s d%uv%u\n", ri->dump_header, action, r->domid, r->vcpuid);
> +}

I know that 'sched_switch_process' used to have '} * r =' type but there
are different pieces of code that do: "} *r =" (mem_pod_zero_reclaim_process)

Could all of the patches use the '*r = ' style? There are more of them:

[konrad@x230 xentrace]$ cat xenalyze.c | grep "} \*r ="   | wc
     32     128     942
[konrad@x230 xentrace]$ cat xenalyze.c | grep "} \* r =" | wc
      3      17      92

Besides that:

Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>


on this and the other patches that touch xenalyze.c (that is with the
modification to * r = ..



>  
>  void sched_process(struct pcpu_info *p)
>  {
> @@ -7573,13 +7568,114 @@ void sched_process(struct pcpu_info *p)
>          default:
>              process_generic(&p->ri);
>          }
> -    } else {
> -        if(ri->evt.sub == 1)
> -            sched_runstate_process(p);
> -        else {
> -            UPDATE_VOLUME(p, sched_verbose, ri->size);
> +        return;
> +    }
> +
> +    if(ri->evt.sub == 1) {
> +        /* TRC_SCHED_MIN */
> +        sched_runstate_process(p);
> +    } else if (ri->evt.sub == 8) {
> +        /* TRC_SCHED_VERBOSE */
> +        switch(ri->event)
> +        {
> +        case TRC_SCHED_DOM_ADD:
> +            if(opt.dump_all) {
> +                struct {
> +                    unsigned int domid;
> +                } * r = (typeof(r))ri->d;
> +
> +                printf(" %s domain create d%u\n", ri->dump_header, r->domid);
> +            }
> +            break;
> +        case TRC_SCHED_DOM_REM:
> +            if(opt.dump_all) {
> +                struct {
> +                    unsigned int domid, vcpuid;
> +                } * r = (typeof(r))ri->d;
> +
> +                printf(" %s domain destroy d%u\n", ri->dump_header, r->domid);
> +            }
> +            break;
> +        case TRC_SCHED_SLEEP:
> +            if(opt.dump_all)
> +                dump_sched_vcpu_action(ri, "vcpu_sleep");
> +            break;
> +        case TRC_SCHED_WAKE:
> +            if(opt.dump_all)
> +                dump_sched_vcpu_action(ri, "vcpu_wake");
> +            break;
> +        case TRC_SCHED_YIELD:
> +            if(opt.dump_all)
> +                dump_sched_vcpu_action(ri, "vcpu_yield");
> +            break;
> +        case TRC_SCHED_BLOCK:
> +            if(opt.dump_all)
> +                dump_sched_vcpu_action(ri, "vcpu_block");
> +            break;
> +        case TRC_SCHED_SHUTDOWN:
> +        case TRC_SCHED_SHUTDOWN_CODE:
> +            if(opt.dump_all) {
> +                struct {
> +                    unsigned int domid, vcpuid, reason;
> +                } * r = (typeof(r))ri->d;
> +
> +                printf(" %s %s d%uv%u, reason = %u\n", ri->dump_header,
> +                       ri->event == TRC_SCHED_SHUTDOWN ? "sched_shutdown" :
> +                       "sched_shutdown_code", r->domid, r->vcpuid, r->reason);
> +            }
> +            break;
> +        case TRC_SCHED_ADJDOM:
> +            if(opt.dump_all) {
> +                struct {
> +                    unsigned int domid;
> +                } * r = (typeof(r))ri->d;
> +
> +                printf(" %s sched_adjust d%u\n", ri->dump_header, r->domid);
> +            }
> +            break;
> +        case TRC_SCHED_SWITCH:
> +            dump_sched_switch(ri);
> +            break;
> +        case TRC_SCHED_SWITCH_INFPREV:
> +            if(opt.dump_all) {
> +                struct {
> +                    unsigned int domid, 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);
> +            }
> +            break;
> +        case TRC_SCHED_SWITCH_INFNEXT:
> +            if(opt.dump_all)
> +            {
> +                struct {
> +                    unsigned int domid, rsince;
> +                    int slice;
> +                } * r = (typeof(r))ri->d;
> +
> +                printf(" %s sched_switch next d%u", ri->dump_header, r->domid);
> +                if ( r->rsince != 0 )
> +                    printf(", was runnable for %u.%uus, ", r->rsince / 1000,
> +                           r->rsince % 1000);
> +                if ( r->slice > 0 )
> +                    printf("next slice %u.%uus\n", 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:
> +        case TRC_SCHED_DOM_TIMER_FN:
> +            break;
> +        default:
>              process_generic(&p->ri);
>          }
> +    } else {
> +        UPDATE_VOLUME(p, sched_verbose, ri->size);
> +        process_generic(&p->ri);
>      }
>  }
>  
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 06/14] xen: sched: tracing: enable TSC tracing for all events
  2016-02-15 16:32   ` Konrad Rzeszutek Wilk
@ 2016-02-15 17:00     ` Dario Faggioli
  0 siblings, 0 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-15 17:00 UTC (permalink / raw)
  To: Konrad Rzeszutek Wilk
  Cc: xen-devel, Olaf Hering, Tianyang Chen, Meng Xu, George Dunlap


[-- Attachment #1.1: Type: text/plain, Size: 2275 bytes --]

On Mon, 2016-02-15 at 11:32 -0500, Konrad Rzeszutek Wilk wrote:
> On Fri, Feb 05, 2016 at 07:34:18PM +0100, Dario Faggioli wrote:
> > it is enabled for pretty much all of them already.
> > There were just a few that had it disabled.
> > 
> > When tracing a scheduler, timing information is
> > really important, so enable it everywhere scheduling
> > related.
> > 
> > Note that this was not really a problem if looking
> > at the traces with xenalyze, but it was if using
> > xentrace_format.
> 
> Was there any historical reason it was not used?
> 
I don't really know.

Funnily enough, for Credit1, it looks like it was me that did it
in cbcbe82f "xen: sched_credit: add some tracing". At the time, Credit2
had some tracing already, and the TRC_CSCHED2_TICKLE was not logging
the TSC.

The only reason I could think of is that, when doing TRC_CSCHED_TICKLE,
I "took inspiration" from what I found already in the code base (yeah,
I know, bad me! :-/).

As per why Credit2 does that in the first place, this is when it
started: 1b561702 "credit2: Fix runq_tickle to use idle, tickled
masks", from George.

In that commit, TRC_CSCHED2_TICKLE_CHECK is moved and, while doing so,
it looses the "TSC logging" property, while TRC_CSCHED2_TICKLE is
introduced from scratch, and that's directly with log_tsc=0.

I can't tell why that is the case, and I think we should change that.

As said in the commit message, xenalyze does not have much problems
with all this, so it's certainly not a super big deal (and it may even
be the reason why this went unnoticed until now, I guess).

However, if looking at the output of xentrace_format (which is a lot
less smart than xenalyze!) it indeed is quite useful to see the
timestamp (not to mention that, without it, the output itself is rather
disturbing to look at and post-process, for severe lack of alignment).

Maybe George knows better, but in any case, I think we should turn this
on. :-)

Thanks and Regards,
Dario
-- 
<<This happens because I choose it to happen!>> (Raistlin Majere)
-----------------------------------------------------------------
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK)


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

^ permalink raw reply	[flat|nested] 31+ messages in thread

* Re: [PATCH 11/14] xenalyze: handle scheduling events
  2016-02-15 16:51   ` Konrad Rzeszutek Wilk
@ 2016-02-15 17:03     ` Dario Faggioli
  0 siblings, 0 replies; 31+ messages in thread
From: Dario Faggioli @ 2016-02-15 17:03 UTC (permalink / raw)
  To: Konrad Rzeszutek Wilk
  Cc: Olaf Hering, Wei Liu, Ian Campbell, George Dunlap, Ian Jackson,
	xen-devel


[-- Attachment #1.1: Type: text/plain, Size: 1679 bytes --]

On Mon, 2016-02-15 at 11:51 -0500, Konrad Rzeszutek Wilk wrote:
> On Fri, Feb 05, 2016 at 07:35:22PM +0100, Dario Faggioli wrote:
> > 
> > @@ -7559,6 +7546,14 @@ void sched_summary_domain(struct domain_data
> > *d)
> >      }
> >  }
> >  
> > +void dump_sched_vcpu_action(struct record_info *ri, const char
> > *action)
> > +{
> > +    struct {
> > +        unsigned int domid, vcpuid;
> > +    } * r = (typeof(r))ri->d;
> > +
> > +    printf(" %s %s d%uv%u\n", ri->dump_header, action, r->domid,
> > r->vcpuid);
> > +}
> 
> I know that 'sched_switch_process' used to have '} * r =' type but
> there
> are different pieces of code that do: "} *r ="
> (mem_pod_zero_reclaim_process)
> 
Ah, good point. I did not notice that, as, as you say, I just
moved/replicated what I found in sched_switch_process.

> Could all of the patches use the '*r = ' style? There are more of
> them:
> 
> [konrad@x230 xentrace]$ cat xenalyze.c | grep "} \*r ="   | wc
>      32     128     942
> [konrad@x230 xentrace]$ cat xenalyze.c | grep "} \* r =" | wc
>       3      17      92
> 
Yep, I'll do this.

> Besides that:
> 
> Reviewed-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
> 
Thanks.

> on this and the other patches that touch xenalyze.c (that is with the
> modification to * r = ..
> 
Sure!

Regards,
Dario
-- 
<<This happens because I choose it to happen!>> (Raistlin Majere)
-----------------------------------------------------------------
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK)


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

[-- Attachment #2: Type: text/plain, Size: 126 bytes --]

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

^ permalink raw reply	[flat|nested] 31+ messages in thread

end of thread, other threads:[~2016-02-15 17:03 UTC | newest]

Thread overview: 31+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-02-05 18:33 [PATCH 00/14] Scheduling related tracing improvements Dario Faggioli
2016-02-05 18:33 ` [PATCH 01/14] xen: sched: __runq_tickle takes a useless cpu parameter Dario Faggioli
2016-02-15 16:14   ` Konrad Rzeszutek Wilk
2016-02-15 16:29     ` Dario Faggioli
2016-02-05 18:33 ` [PATCH 02/14] xen: sched: move up the trace record for vcpu_wake and vcpu_sleep Dario Faggioli
2016-02-15 16:18   ` Konrad Rzeszutek Wilk
2016-02-05 18:33 ` [PATCH 03/14] xen: sched: fi position of TRC_SCHED_DOM_{ADD, REM} Dario Faggioli
2016-02-15 16:22   ` Konrad Rzeszutek Wilk
2016-02-15 16:37     ` Dario Faggioli
2016-02-15 16:41       ` Konrad Rzeszutek Wilk
2016-02-05 18:33 ` [PATCH 04/14] xen: credit2: pack trace data better for xentrace_format Dario Faggioli
2016-02-15 16:29   ` Konrad Rzeszutek Wilk
2016-02-05 18:34 ` [PATCH 05/14] xen: RTDS: " Dario Faggioli
2016-02-15 16:31   ` Konrad Rzeszutek Wilk
2016-02-05 18:34 ` [PATCH 06/14] xen: sched: tracing: enable TSC tracing for all events Dario Faggioli
2016-02-15 16:32   ` Konrad Rzeszutek Wilk
2016-02-15 17:00     ` Dario Faggioli
2016-02-05 18:34 ` [PATCH 07/14] xentrace: formats: update format of scheduling events Dario Faggioli
2016-02-15 16:38   ` Konrad Rzeszutek Wilk
2016-02-15 16:42     ` Dario Faggioli
2016-02-05 18:34 ` [PATCH 08/14] xentrace: formats: add events from Credit scheduler Dario Faggioli
2016-02-15 16:40   ` Konrad Rzeszutek Wilk
2016-02-05 18:34 ` [PATCH 09/14] xentrace: formats: add events from Credit2 scheduler Dario Faggioli
2016-02-15 16:44   ` Konrad Rzeszutek Wilk
2016-02-05 18:35 ` [PATCH 10/14] xentrace: formats: add events from RTDS scheduler Dario Faggioli
2016-02-05 18:35 ` [PATCH 11/14] xenalyze: handle scheduling events Dario Faggioli
2016-02-15 16:51   ` Konrad Rzeszutek Wilk
2016-02-15 17:03     ` Dario Faggioli
2016-02-05 18:35 ` [PATCH 12/14] xenalyze: handle Credit1 scheduler events Dario Faggioli
2016-02-05 18:35 ` [PATCH 13/14] xenalyze: handle Credit2 " Dario Faggioli
2016-02-05 18:35 ` [PATCH 14/14] xenalyze: handle RTDS " Dario Faggioli

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.