Scheduling related tracing improvements

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 <[email protected]>

---
Cc: George Dunlap <[email protected]>

---
 xen/common/sched_credit.c |   10 ++++------
 1 file changed, 4 insertions(+), 6 deletions(-)

xen/common/sched_credit.c +4 -6

index 671bbee..5279b92 100644
@@ -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
[email protected]
http://lists.xen.org/xen-devel

Quoted 2 lines · Dario Faggioli

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

s/because of which// ?

Reviewed-by Konrad Rzeszutek Wilk <[email protected]>

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 <[email protected]>

---
Cc: George Dunlap <[email protected]>

---
 xen/common/schedule.c |   16 ++++++++++------
 1 file changed, 10 insertions(+), 6 deletions(-)

xen/common/schedule.c +10 -6

index 7306d71..c87922f 100644
@@ -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
[email protected]
http://lists.xen.org/xen-devel

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

Signed-off-by Dario Faggioli <[email protected]>

---
Cc: George Dunlap <[email protected]>

---
 xen/common/domain.c   |    1 -
 xen/common/schedule.c |    4 ++--
 2 files changed, 2 insertions(+), 3 deletions(-)

xen/common/domain.c +0 -1

index 425767c..ddc7484 100644
@@ -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 ) 

xen/common/schedule.c +2 -2

index c87922f..27695e3 100644
@@ -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
[email protected]
http://lists.xen.org/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'.

Quoted 4 lines

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

Quoted 1 line

Signed-off-by Dario Faggioli <[email protected]>

.. 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)?

Quoted 4 lines · Konrad Rzeszutek Wilk

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.

Quoted 4 lines

Quoted 4 lines

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

Quoted 9 lines

Quoted 1 line

Signed-off-by Dario Faggioli <[email protected]>

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

Signature · 4 lines

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

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 <[email protected]>

---
Cc: George Dunlap <[email protected]>
Cc: Olaf Hering <[email protected]>

---
 xen/common/sched_credit2.c |   16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

xen/common/sched_credit2.c +8 -8

index 78220a7..cf40f68 100644
@@ -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
[email protected]
http://lists.xen.org/xen-devel

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 <[email protected]>

---
Cc: George Dunlap <[email protected]>
Cc: Meng Xu <[email protected]>
Cc: Tianyang Chen <[email protected]>
Cc: Olaf Hering <[email protected]>

---
 xen/common/sched_rt.c |   27 ++++-----------------------
 1 file changed, 4 insertions(+), 23 deletions(-)

xen/common/sched_rt.c +4 -23

index 2e5430f..53de6d6 100644
@@ -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
[email protected]
http://lists.xen.org/xen-devel

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 <[email protected]>

---
Cc: George Dunlap <[email protected]>
Cc: Meng Xu <[email protected]>
Cc: Tianyang Chen <[email protected]>
Cc: Olaf Hering <[email protected]>

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

xen/common/sched_credit.c +1 -1

index 5279b92..bd2f37f 100644
@@ -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 */

xen/common/sched_credit2.c +3 -3

index cf40f68..2934e26 100644
@@ -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

xen/common/sched_rt.c +1 -1

index 53de6d6..33ac9de 100644
@@ -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
[email protected]
http://lists.xen.org/xen-devel

Quoted 7 lines · Dario Faggioli

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.

Quoted 3 lines

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?

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 <[email protected]>

---
Cc: George Dunlap <[email protected]>
Cc: Ian Jackson <[email protected]>
Cc: Ian Campbell <[email protected]>
Cc: Wei Liu <[email protected]>
Cc: Olaf Hering <[email protected]>

---
 tools/xentrace/formats |   18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)

tools/xentrace/formats +9 -9

index 5d7b72a..5257cf0 100644
@@ -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
[email protected]
http://lists.xen.org/xen-devel

Quoted 3 lines · Dario Faggioli

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 <[email protected]>

Signed-off-by Dario Faggioli <[email protected]>

---
Cc: George Dunlap <[email protected]>
Cc: Ian Jackson <[email protected]>
Cc: Ian Campbell <[email protected]>
Cc: Wei Liu <[email protected]>
Cc: Olaf Hering <[email protected]>

---
 tools/xentrace/formats |    7 +++++++
 1 file changed, 7 insertions(+)

tools/xentrace/formats +7 -0

index 5257cf0..a5636e9 100644
@@ -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
[email protected]
http://lists.xen.org/xen-devel

Signed-off-by Dario Faggioli <[email protected]>

---
Cc: George Dunlap <[email protected]>
Cc: Ian Jackson <[email protected]>
Cc: Ian Campbell <[email protected]>
Cc: Wei Liu <[email protected]>
Cc: Olaf Hering <[email protected]>

---
 tools/xentrace/formats |   13 +++++++++++++
 1 file changed, 13 insertions(+)

tools/xentrace/formats +3 -0

index a5636e9..b8ec06b 100644
@@ -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 ]

tools/xentrace/formats +0 -0

 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
[email protected]
http://lists.xen.org/xen-devel

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

Signed-off-by Dario Faggioli <[email protected]>

---
Cc: George Dunlap <[email protected]>
Cc: Ian Jackson <[email protected]>
Cc: Ian Campbell <[email protected]>
Cc: Wei Liu <[email protected]>
Cc: Olaf Hering <[email protected]>

---
 tools/xentrace/xenalyze.c |  156 ++++++++++++++++++++++++++++++++++++---------
 1 file changed, 126 insertions(+), 30 deletions(-)

tools/xentrace/xenalyze.c +12 -25

index 6520790..be698aa 100644
@@ -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)
     }

tools/xentrace/xenalyze.c +106 -5

 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
[email protected]
http://lists.xen.org/xen-devel

Quoted 13 lines · Dario Faggioli

(quoted diff) +0 -0

@@ -7559,6 +7546,14 @@ void sched_summary_domain(struct domain_data
 *d)
      }
  }

+void dump_sched_vcpu_action(struct record_info *ri, const char *action)

tools/xentrace/xenalyze.c +5 -0

+{
+    struct {
+        unsigned int domid, vcpuid;
+    } * r = (typeof(r))ri->d;
+

Quoted 3 lines

+    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 <[email protected]>

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