diff mbox

[06/14] xen: sched: tracing: enable TSC tracing for all events

Message ID 20160205183418.4543.5548.stgit@Solace.station (mailing list archive)
State New, archived
Headers show

Commit Message

Dario Faggioli Feb. 5, 2016, 6:34 p.m. UTC
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(-)

Comments

Konrad Rzeszutek Wilk Feb. 15, 2016, 4:32 p.m. UTC | #1
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
Dario Faggioli Feb. 15, 2016, 5 p.m. UTC | #2
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
diff mbox

Patch

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