Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Frederic Weisbecker]

On Wed, Jun 07, 2017 at 04:17:41AM +0000, Levin, Alexander (Sasha Levin) wrote:
> > Thanks Sasha!
> > 
> > I couldn't reproduce it, that config boots fine on my kvm.
> > Would you have the time to dump some traces for me?
> > 
> > I'd need you to add this boot option: trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry
> > And boot your kernel with the below patch. This will dump the timer traces to your console.
> > I would be very interested in the resulting console dump file.
> 
> Attached. Let me know if you need anything else.

Great! So now I can deduce that the problem doesn't come from the nohz code as
ts->next_tick matches the hrtimer deadline. But the dev->next_event from the
clockevent seems to be out of line.

Sorry to bother you again, but I'm chasing this bug for several weeks now and
you're one of the rare person who can reproduce it. So I may need some more
tracing details.

Here is another version of the debugging patch (not a delta), I added more trace_printk,
namely the places where we set this dev->next_event. Can you please apply the below and do
the dump again?

I'm adding a boot option as well for the stacktrace:

trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry trace_options=stacktrace

Thanks a lot!

diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c
index 4237e07..e21e929 100644
--- a/kernel/time/clockevents.c
+++ b/kernel/time/clockevents.c
@@ -180,6 +180,7 @@ void clockevents_shutdown(struct clock_event_device *dev)
 {
 	clockevents_switch_state(dev, CLOCK_EVT_STATE_SHUTDOWN);
 	dev->next_event = KTIME_MAX;
+	trace_printk("dev->next_event: %llu\n", dev->next_event);
 }
 
 /**
@@ -214,6 +215,7 @@ static int clockevents_increase_min_delta(struct clock_event_device *dev)
 		printk_deferred(KERN_WARNING
 				"CE: Reprogramming failure. Giving up\n");
 		dev->next_event = KTIME_MAX;
+		trace_printk("dev->next_event: %llu\n", dev->next_event);
 		return -ETIME;
 	}
 
@@ -247,6 +249,7 @@ static int clockevents_program_min_delta(struct clock_event_device *dev)
 	for (i = 0;;) {
 		delta = dev->min_delta_ns;
 		dev->next_event = ktime_add_ns(ktime_get(), delta);
+		trace_printk("dev->next_event: %llu\n", dev->next_event);
 
 		if (clockevent_state_shutdown(dev))
 			return 0;
@@ -284,6 +287,7 @@ static int clockevents_program_min_delta(struct clock_event_device *dev)
 
 	delta = dev->min_delta_ns;
 	dev->next_event = ktime_add_ns(ktime_get(), delta);
+	trace_printk("dev->next_event: %llu\n", dev->next_event);
 
 	if (clockevent_state_shutdown(dev))
 		return 0;
@@ -316,6 +320,7 @@ int clockevents_program_event(struct clock_event_device *dev, ktime_t expires,
 	}
 
 	dev->next_event = expires;
+	trace_printk("dev->next_event: %llu\n", dev->next_event);
 
 	if (clockevent_state_shutdown(dev))
 		return 0;
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 2de9c55..ad1de28 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -156,6 +156,7 @@ static void tick_sched_handle(struct tick_sched *ts, struct pt_regs *regs)
 		 * to the same deadline.
 		 */
 		ts->next_tick = 0;
+		trace_printk("ts->next_tick reset (tick)\n");
 	}
 #endif
 	update_process_times(user_mode(regs));
@@ -672,6 +673,7 @@ static void tick_nohz_restart(struct tick_sched *ts, ktime_t now)
 	 * cached clock deadline.
 	 */
 	ts->next_tick = 0;
+	trace_printk("ts->next_tick reset (tick restart)\n");
 }
 
 static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
@@ -788,6 +790,11 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 		if (likely(dev->next_event <= ts->next_tick))
 			goto out;
 
+		trace_printk("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
+			    basemono, ts->next_tick, dev->next_event,
+			    hrtimer_active(&ts->sched_timer), hrtimer_get_expires(&ts->sched_timer));
+		tracing_stop();
+		ftrace_dump(DUMP_ORIG);
 		WARN_ON_ONCE(1);
 		printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
 			    basemono, ts->next_tick, dev->next_event,
@@ -812,6 +819,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	}
 
 	ts->next_tick = tick;
+	trace_printk("ts->next_tick = %llu\n", ts->next_tick);
 
 	/*
 	 * If the expiration time == KTIME_MAX, then we simply stop
@@ -894,6 +902,7 @@ static bool can_stop_idle_tick(int cpu, struct tick_sched *ts)
 		 * deadline if it comes back online later.
 		 */
 		ts->next_tick = 0;
+		trace_printk("ts->next_tick reset (offline)\n");
 		return false;
 	}
 
@@ -1202,8 +1211,10 @@ static enum hrtimer_restart tick_sched_timer(struct hrtimer *timer)
 	 */
 	if (regs)
 		tick_sched_handle(ts, regs);
-	else
+	else {
+		trace_printk("ts->next_tick reset (tick)\n");
 		ts->next_tick = 0;
+	}
 
 	/* No need to reprogram if we are in idle or full dynticks mode */
 	if (unlikely(ts->tick_stopped))