Re: [Xen-devel] [PATCH 13/19] xen: credit2: make the code less experimental

[Dario Faggioli]

On Thu, 2016-07-07 at 16:17 +0100, George Dunlap wrote:
> On Sat, Jun 18, 2016 at 12:12 AM, Dario Faggioli
>  wrote:
> > @@ -680,8 +677,8 @@ __update_svc_load(const struct scheduler *ops,
> >  delta = now - svc->load_last_update;
> >  if ( unlikely(delta < 0) )
> >  {
> > -d2printk("%s: Time went backwards? now %"PRI_stime"
> > llu %"PRI_stime"\n",
> > - __func__, now, svc->load_last_update);
> > +printk("WARNING: %s: Time went backwards? now
> > %"PRI_stime" llu %"PRI_stime"\n",
> > +   __func__, now, svc->load_last_update);
> Hmm, I'm afraid this makes all Jan's comments from patch 7 which I
> argued against since it was just a debugging message now valid.
> 
Yes, and on second thoughts --as I wrote myself earlier today-- I think
we actually want to keep these debug only.

I'll make things that way when resending.

> > @@ -1540,9 +1536,26 @@ static void migrate(const struct scheduler
> > *ops,
> >  struct csched2_runqueue_data *trqd,
> >  s_time_t now)
> >  {
> > -if ( svc->flags & CSFLAG_scheduled )
> > +bool_t running = svc->flags & CSFLAG_scheduled;
> > +bool_t on_runq = __vcpu_on_runq(svc);
> What's the point of having these variables here?  AFAICS 'running' is
> used exactly once; and on_runq is only used inside the original else
> {
> } clause where it was before.
> 
Mmm... not much indeed. AFAICR, it's a remnant from a previous version
of the patch. Sorry.

> > @@ -2069,12 +2076,13 @@ csched2_schedule(
> >  }
> >  }
> >  }
> > -printk("%s: pcpu %d rq %d, but scurr %pv assigned to "
> > +printk("DEBUG: %s: pcpu %d rq %d, but scurr %pv assigned
> > to "
> > "pcpu %d rq %d!\n",
> > __func__,
> > cpu, this_rqi,
> > scurr->vcpu, scurr->vcpu->processor, other_rqi);
> >  }
> > +#endif
> Do we need this path anymore? I think it was just there to help
> debugging; but all this should have been sorted out a long time ago.
> :-)
> 
Right. I'm more than up for killing it.

Thanks and Regards,
Dario
-- 
<> (Raistlin Majere)
-
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R Ltd., Cambridge (UK)



signature.asc
Description: This is a digitally signed message part
___
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel

Re: [Xen-devel] [PATCH 13/19] xen: credit2: make the code less experimental

[George Dunlap]

On Sat, Jun 18, 2016 at 12:12 AM, Dario Faggioli
 wrote:
> Mainly, almost all of the BUG_ON-s can be converted into
> ASSERTS, and the debug printk either removed or turned
> into tracing.
>
> The 'TODO' list, in a comment at the beginning of the file,
> was also stale, so remove items that were still there but
> are actually done.
>
> Signed-off-by: Dario Faggioli 

Overall looks good.  A couple of things...

> @@ -680,8 +677,8 @@ __update_svc_load(const struct scheduler *ops,
>  delta = now - svc->load_last_update;
>  if ( unlikely(delta < 0) )
>  {
> -d2printk("%s: Time went backwards? now %"PRI_stime" llu 
> %"PRI_stime"\n",
> - __func__, now, svc->load_last_update);
> +printk("WARNING: %s: Time went backwards? now %"PRI_stime" llu 
> %"PRI_stime"\n",
> +   __func__, now, svc->load_last_update);

Hmm, I'm afraid this makes all Jan's comments from patch 7 which I
argued against since it was just a debugging message now valid.

> @@ -1540,9 +1536,26 @@ static void migrate(const struct scheduler *ops,
>  struct csched2_runqueue_data *trqd,
>  s_time_t now)
>  {
> -if ( svc->flags & CSFLAG_scheduled )
> +bool_t running = svc->flags & CSFLAG_scheduled;
> +bool_t on_runq = __vcpu_on_runq(svc);

What's the point of having these variables here?  AFAICS 'running' is
used exactly once; and on_runq is only used inside the original else {
} clause where it was before.

> @@ -2069,12 +2076,13 @@ csched2_schedule(
>  }
>  }
>  }
> -printk("%s: pcpu %d rq %d, but scurr %pv assigned to "
> +printk("DEBUG: %s: pcpu %d rq %d, but scurr %pv assigned to "
> "pcpu %d rq %d!\n",
> __func__,
> cpu, this_rqi,
> scurr->vcpu, scurr->vcpu->processor, other_rqi);
>  }
> +#endif

Do we need this path anymore? I think it was just there to help
debugging; but all this should have been sorted out a long time ago.
:-)

Thanks,
 -George

___
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel

Re: [Xen-devel] [PATCH 13/19] xen: credit2: make the code less experimental

[Dario Faggioli]

On Mon, 2016-06-20 at 02:13 -0600, Jan Beulich wrote:
> > > > On 18.06.16 at 01:12,  wrote:
> > @@ -680,8 +677,8 @@ __update_svc_load(const struct scheduler *ops,
> >  delta = now - svc->load_last_update;
> >  if ( unlikely(delta < 0) )
> >  {
> > -d2printk("%s: Time went backwards? now %"PRI_stime"
> > llu %"PRI_stime"\n",
> > - __func__, now, svc->load_last_update);
> > +printk("WARNING: %s: Time went backwards? now
> > %"PRI_stime" llu %"PRI_stime"\n",
> > +   __func__, now, svc->load_last_update);
> >  delta = 0;
> >  }
> >  
> With these now becoming non-debugging ones - are they useful
> _every_ time such an event occurs? I.e. wouldn't it be better to
> e.g. only log new high watermark values?
>
Actually, I may want to reconsider this specific hunk (and the other
similar ones using printk instead of d2printk for 'time going
backwards' debug lines).

It's useful, but I'm not sure I want it printing all the time.

So hold off committing this patch, please (this is probably not
necessary to say, given the issue below, but just in case...)

> > @@ -2580,15 +2583,20 @@ csched2_init(struct scheduler *ops)
> >  int i;
> >  struct csched2_private *prv;
> >  
> > -printk("Initializing Credit2 scheduler\n" \
> > -   " WARNING: This is experimental software in
> > development.\n" \
> > +printk("Initializing Credit2 scheduler\n");
> > +printk(" WARNING: This is experimental software in
> > development.\n" \
> > " Use at your own risk.\n");
> >  
> > -printk(" load_precision_shift: %d\n",
> > opt_load_precision_shift);
> > -printk(" load_window_shift: %d\n", opt_load_window_shift);
> > -printk(" underload_balance_tolerance: %d\n",
> > opt_underload_balance_tolerance);
> > -printk(" overload_balance_tolerance: %d\n",
> > opt_overload_balance_tolerance);
> > -printk(" runqueues arrangement: %s\n",
> > opt_runqueue_str[opt_runqueue]);
> > +printk(XENLOG_INFO " load_precision_shift: %d\n"
> > +   " load_window_shift: %d\n"
> > +   " underload_balance_tolerance: %d\n"
> > +   " overload_balance_tolerance: %d\n"
> > +   " runqueues arrangement: %s\n",
> > +   opt_load_precision_shift,
> > +   opt_load_window_shift,
> > +   opt_underload_balance_tolerance,
> > +   opt_overload_balance_tolerance,
> > +   opt_runqueue_str[opt_runqueue]);
> Note that this results in only the first line getting logged at info
> level;
> all others will get the default logging level (i.e. warning)
> assigned. IOW
> I think you want to repeat XENLOG_INFO a couple of times.
> 
You know what, I did not notice that, sorry! Yes, I'll fix this.

Thanks and Regards,
Dario
-- 
<> (Raistlin Majere)
-
Dario Faggioli, Ph.D, http://about.me/dario.faggioli
Senior Software Engineer, Citrix Systems R Ltd., Cambridge (UK)



signature.asc
Description: This is a digitally signed message part
___
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel

Re: [Xen-devel] [PATCH 13/19] xen: credit2: make the code less experimental

[Jan Beulich]

>>> On 18.06.16 at 01:12,  wrote:
> @@ -608,8 +605,8 @@ __update_runq_load(const struct scheduler *ops,
>  delta = now - rqd->load_last_update;
>  if ( unlikely(delta < 0) )
>  {
> -d2printk("%s: Time went backwards? now %"PRI_stime" llu 
> %"PRI_stime"\n",
> - __func__, now, rqd->load_last_update);
> +printk("WARNING: %s: Time went backwards? now %"PRI_stime" llu 
> %"PRI_stime"\n",
> +   __func__, now, rqd->load_last_update);
>  delta = 0;
>  }
>  
> @@ -680,8 +677,8 @@ __update_svc_load(const struct scheduler *ops,
>  delta = now - svc->load_last_update;
>  if ( unlikely(delta < 0) )
>  {
> -d2printk("%s: Time went backwards? now %"PRI_stime" llu 
> %"PRI_stime"\n",
> - __func__, now, svc->load_last_update);
> +printk("WARNING: %s: Time went backwards? now %"PRI_stime" llu 
> %"PRI_stime"\n",
> +   __func__, now, svc->load_last_update);
>  delta = 0;
>  }
>  

With these now becoming non-debugging ones - are they useful
_every_ time such an event occurs? I.e. wouldn't it be better to
e.g. only log new high watermark values?

> @@ -2580,15 +2583,20 @@ csched2_init(struct scheduler *ops)
>  int i;
>  struct csched2_private *prv;
>  
> -printk("Initializing Credit2 scheduler\n" \
> -   " WARNING: This is experimental software in development.\n" \
> +printk("Initializing Credit2 scheduler\n");
> +printk(" WARNING: This is experimental software in development.\n" \
> " Use at your own risk.\n");
>  
> -printk(" load_precision_shift: %d\n", opt_load_precision_shift);
> -printk(" load_window_shift: %d\n", opt_load_window_shift);
> -printk(" underload_balance_tolerance: %d\n", 
> opt_underload_balance_tolerance);
> -printk(" overload_balance_tolerance: %d\n", 
> opt_overload_balance_tolerance);
> -printk(" runqueues arrangement: %s\n", opt_runqueue_str[opt_runqueue]);
> +printk(XENLOG_INFO " load_precision_shift: %d\n"
> +   " load_window_shift: %d\n"
> +   " underload_balance_tolerance: %d\n"
> +   " overload_balance_tolerance: %d\n"
> +   " runqueues arrangement: %s\n",
> +   opt_load_precision_shift,
> +   opt_load_window_shift,
> +   opt_underload_balance_tolerance,
> +   opt_overload_balance_tolerance,
> +   opt_runqueue_str[opt_runqueue]);

Note that this results in only the first line getting logged at info level;
all others will get the default logging level (i.e. warning) assigned. IOW
I think you want to repeat XENLOG_INFO a couple of times.

Jan


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

[Xen-devel] [PATCH 13/19] xen: credit2: make the code less experimental

[Dario Faggioli]

Mainly, almost all of the BUG_ON-s can be converted into
ASSERTS, and the debug printk either removed or turned
into tracing.

The 'TODO' list, in a comment at the beginning of the file,
was also stale, so remove items that were still there but
are actually done.

Signed-off-by: Dario Faggioli 
---
Cc: George Dunlap 
Cc: Anshul Makkar 
Cc: David Vrabel 
---
 xen/common/sched_credit2.c |  244 +++-
 1 file changed, 126 insertions(+), 118 deletions(-)

diff --git a/xen/common/sched_credit2.c b/xen/common/sched_credit2.c
index 2ca63ae..ba3a78a 100644
--- a/xen/common/sched_credit2.c
+++ b/xen/common/sched_credit2.c
@@ -27,9 +27,6 @@
 #include 
 #include 
 
-#define d2printk(x...)
-//#define d2printk printk
-
 /*
  * Credit2 tracing events ("only" 512 available!). Check
  * include/public/trace.h for more details.
@@ -46,16 +43,16 @@
 #define TRC_CSCHED2_RUNQ_ASSIGN  TRC_SCHED_CLASS_EVT(CSCHED2, 10)
 #define TRC_CSCHED2_UPDATE_VCPU_LOAD TRC_SCHED_CLASS_EVT(CSCHED2, 11)
 #define TRC_CSCHED2_UPDATE_RUNQ_LOAD TRC_SCHED_CLASS_EVT(CSCHED2, 12)
+#define TRC_CSCHED2_TICKLE_NEW   TRC_SCHED_CLASS_EVT(CSCHED2, 13)
+#define TRC_CSCHED2_RUNQ_MAX_WEIGHT  TRC_SCHED_CLASS_EVT(CSCHED2, 14)
+#define TRC_CSCHED2_MIGRATE  TRC_SCHED_CLASS_EVT(CSCHED2, 15)
 
 /*
  * WARNING: This is still in an experimental phase.  Status and work can be 
found at the
  * credit2 wiki page:
  *  http://wiki.xen.org/wiki/Credit2_Scheduler_Development
+ *
  * TODO:
- * + Multiple sockets
- *  - Simple load balancer / runqueue assignment
- *  - Runqueue load measurement
- *  - Load-based load balancer
  * + Hyperthreading
  *  - Look for non-busy core if possible
  *  - "Discount" time run on a thread with busy siblings
@@ -608,8 +605,8 @@ __update_runq_load(const struct scheduler *ops,
 delta = now - rqd->load_last_update;
 if ( unlikely(delta < 0) )
 {
-d2printk("%s: Time went backwards? now %"PRI_stime" llu 
%"PRI_stime"\n",
- __func__, now, rqd->load_last_update);
+printk("WARNING: %s: Time went backwards? now %"PRI_stime" llu 
%"PRI_stime"\n",
+   __func__, now, rqd->load_last_update);
 delta = 0;
 }
 
@@ -680,8 +677,8 @@ __update_svc_load(const struct scheduler *ops,
 delta = now - svc->load_last_update;
 if ( unlikely(delta < 0) )
 {
-d2printk("%s: Time went backwards? now %"PRI_stime" llu 
%"PRI_stime"\n",
- __func__, now, svc->load_last_update);
+printk("WARNING: %s: Time went backwards? now %"PRI_stime" llu 
%"PRI_stime"\n",
+   __func__, now, svc->load_last_update);
 delta = 0;
 }
 
@@ -723,23 +720,18 @@ __runq_insert(struct list_head *runq, struct csched2_vcpu 
*svc)
 struct list_head *iter;
 int pos = 0;
 
-d2printk("rqi %pv\n", svc->vcpu);
-
-BUG_ON(>rqd->runq != runq);
-/* Idle vcpus not allowed on the runqueue anymore */
-BUG_ON(is_idle_vcpu(svc->vcpu));
-BUG_ON(svc->vcpu->is_running);
-BUG_ON(svc->flags & CSFLAG_scheduled);
+ASSERT(>rqd->runq == runq);
+ASSERT(!is_idle_vcpu(svc->vcpu));
+ASSERT(!svc->vcpu->is_running);
+ASSERT(!(svc->flags & CSFLAG_scheduled));
 
 list_for_each( iter, runq )
 {
 struct csched2_vcpu * iter_svc = __runq_elem(iter);
 
 if ( svc->credit > iter_svc->credit )
-{
-d2printk(" p%d %pv\n", pos, iter_svc->vcpu);
 break;
-}
+
 pos++;
 }
 
@@ -755,10 +747,10 @@ runq_insert(const struct scheduler *ops, struct 
csched2_vcpu *svc)
 struct list_head * runq = (ops, cpu)->runq;
 int pos = 0;
 
-ASSERT( spin_is_locked(per_cpu(schedule_data, cpu).schedule_lock) );
+ASSERT(spin_is_locked(per_cpu(schedule_data, cpu).schedule_lock));
 
-BUG_ON( __vcpu_on_runq(svc) );
-BUG_ON( c2r(ops, cpu) != c2r(ops, svc->vcpu->processor) );
+ASSERT(!__vcpu_on_runq(svc));
+ASSERT(c2r(ops, cpu) == c2r(ops, svc->vcpu->processor));
 
 pos = __runq_insert(runq, svc);
 
@@ -781,7 +773,7 @@ runq_insert(const struct scheduler *ops, struct 
csched2_vcpu *svc)
 static inline void
 __runq_remove(struct csched2_vcpu *svc)
 {
-BUG_ON( !__vcpu_on_runq(svc) );
+ASSERT(__vcpu_on_runq(svc));
 list_del_init(>runq_elem);
 }
 
@@ -806,16 +798,29 @@ void burn_credits(struct csched2_runqueue_data *rqd, 
struct csched2_vcpu *, s_ti
 static void
 runq_tickle(const struct scheduler *ops, struct csched2_vcpu *new, s_time_t 
now)
 {
-int i, ipid=-1;
-s_time_t lowest=(1<<30);
+int i, ipid = -1;
+s_time_t lowest = (1<<30);
 unsigned int cpu = new->vcpu->processor;
 struct csched2_runqueue_data *rqd = RQD(ops, cpu);
 cpumask_t mask;
 struct csched2_vcpu * cur;
 
-d2printk("rqt %pv curr %pv\n",