tracingtimers/testing

6 files changed, 150 insertions, 8 deletions

diff --git a/drivers/cpuidle/cpuidle.c b/drivers/cpuidle/cpuidle.c
index 737a026ef58a3..082a6648ccfce 100644
--- a/drivers/cpuidle/cpuidle.c
+++ b/drivers/cpuidle/cpuidle.c
@@ -27,7 +27,7 @@
 #include <linux/mmu_context.h>
 #include <linux/context_tracking.h>
 #include <trace/events/power.h>
-
+#include <trace/events/sched.h>
 #include "cpuidle.h"
 
 DEFINE_PER_CPU(struct cpuidle_device *, cpuidle_devices);
@@ -219,7 +219,7 @@ noinstr int cpuidle_enter_state(struct cpuidle_device *dev,
 	ktime_t time_start, time_end;
 
 	instrumentation_begin();
-
+//	trace_sched_nr(2);
 	/*
 	 * Tell the time framework to switch to a broadcast timer because our
 	 * local timer will be shut down.  If a local timer is used from another
@@ -235,7 +235,7 @@ noinstr int cpuidle_enter_state(struct cpuidle_device *dev,
 		target_state = &drv->states[index];
 		broadcast = false;
 	}
-
+//	trace_sched_nr(3);
 	if (target_state->flags & CPUIDLE_FLAG_TLB_FLUSHED)
 		leave_mm(dev->cpu);
 
@@ -334,6 +334,7 @@ noinstr int cpuidle_enter_state(struct cpuidle_device *dev,
 		dev->last_residency_ns = 0;
 		dev->states_usage[index].rejected++;
 	}
+//	trace_sched_nr(4);
 
 	instrumentation_end();
 
diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index dbb01b4b74510..a4ae3f149b9f8 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -10,6 +10,40 @@
 #include <linux/tracepoint.h>
 #include <linux/binfmts.h>
 
+TRACE_EVENT(sched_trace_printk,
+
+	TP_PROTO(const char *bpf_string),
+
+	TP_ARGS(bpf_string),
+
+	TP_STRUCT__entry(
+		__string(bpf_string, bpf_string)
+	),
+
+	TP_fast_assign(
+		__assign_str(bpf_string, bpf_string);
+	),
+
+	TP_printk("%s", __get_str(bpf_string))
+);
+
+TRACE_EVENT(sched_nr,
+
+	TP_PROTO(int nr),
+
+	TP_ARGS(nr),
+
+	TP_STRUCT__entry(
+		__field(	int,	nr			)
+	),
+
+	TP_fast_assign(
+		__entry->nr	= nr;
+	),
+
+	TP_printk("%d", __entry->nr)
+);
+
 /*
  * Tracepoint for calling kthread_stop, performed to end a kthread:
  */
diff --git a/include/trace/events/timer_migration.h b/include/trace/events/timer_migration.h
index 79f19e76a80bf..466e79ac76d7e 100644
--- a/include/trace/events/timer_migration.h
+++ b/include/trace/events/timer_migration.h
@@ -8,6 +8,52 @@
 
 #include <linux/tracepoint.h>
 
+TRACE_EVENT(timer_trace_printk,
+
+	TP_PROTO(const char *bpf_string),
+
+	TP_ARGS(bpf_string),
+
+	TP_STRUCT__entry(
+		__string(bpf_string, bpf_string)
+	),
+
+	TP_fast_assign(
+		__assign_str(bpf_string, bpf_string);
+	),
+
+	TP_printk("%s", __get_str(bpf_string))
+);
+
+/* Group events */
+TRACE_EVENT(tmigr_fetched,
+
+	    TP_PROTO(u64 basem, u64 local, u64 global, int idle, int is_idle, int idle_is_possible),
+
+	    TP_ARGS(basem, local, global, idle, is_idle, idle_is_possible),
+
+	TP_STRUCT__entry(
+		__field( unsigned long long,	basem		)
+		__field( unsigned long long,	local		)
+		__field( unsigned long long,	global		)
+		__field( int,	idle		)
+		__field( int,	is_idle		)
+		__field( int,	idle_is_possible		)
+	),
+
+	TP_fast_assign(
+		__entry->basem		= basem;
+		__entry->local		= local;
+		__entry->global	= global;
+		__entry->idle	= idle;
+		__entry->is_idle	= is_idle;
+		__entry->idle_is_possible	= idle_is_possible;
+	),
+
+	TP_printk("basem:%llu local: %llu global: %llu idle: %d is_idle: %d idle_is_possible:%d",
+		  __entry->basem, __entry->local, __entry->global, __entry->idle, __entry->is_idle, __entry->idle_is_possible)
+);
+
 /* Group events */
 TRACE_EVENT(tmigr_group_set,
 
diff --git a/kernel/sched/idle.c b/kernel/sched/idle.c
index 31231925f1ece..ca2602f5fe1d6 100644
--- a/kernel/sched/idle.c
+++ b/kernel/sched/idle.c
@@ -9,7 +9,6 @@
 
 /* Linker adds these: start and end of __cpuidle functions */
 extern char __cpuidle_text_start[], __cpuidle_text_end[];
-
 /**
  * sched_idle_set_state - Record idle state for the current CPU.
  * @idle_state: State to record.
@@ -89,7 +88,9 @@ void __weak arch_cpu_idle(void)
 void __cpuidle default_idle_call(void)
 {
 	instrumentation_begin();
+//	trace_sched_nr(6);
 	if (!current_clr_polling_and_test()) {
+//		trace_sched_nr(7);
 		trace_cpu_idle(1, smp_processor_id());
 		stop_critical_timings();
 
@@ -100,6 +101,7 @@ void __cpuidle default_idle_call(void)
 		start_critical_timings();
 		trace_cpu_idle(PWR_EVENT_EXIT, smp_processor_id());
 	}
+//	trace_sched_nr(8);
 	local_irq_enable();
 	instrumentation_end();
 }
@@ -116,6 +118,7 @@ static int call_cpuidle_s2idle(struct cpuidle_driver *drv,
 static int call_cpuidle(struct cpuidle_driver *drv, struct cpuidle_device *dev,
 		      int next_state)
 {
+//	trace_sched_nr(0);
 	/*
 	 * The idle task must be scheduled, it is pointless to go to idle, just
 	 * update no idle residency and return.
@@ -125,6 +128,7 @@ static int call_cpuidle(struct cpuidle_driver *drv, struct cpuidle_device *dev,
 		local_irq_enable();
 		return -EBUSY;
 	}
+//	trace_sched_nr(1);
 
 	/*
 	 * Enter the idle state previously returned by the governor decision.
@@ -165,8 +169,8 @@ static void cpuidle_idle_call(void)
 	 */
 
 	if (cpuidle_not_available(drv, dev)) {
+		//trace_sched_nr(5);
 		tick_nohz_idle_stop_tick();
-
 		default_idle_call();
 		goto exit_idle;
 	}
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 417bb7f880ca0..b353d380ae84d 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -26,6 +26,7 @@
 #include <linux/posix-timers.h>
 #include <linux/context_tracking.h>
 #include <linux/mm.h>
+#include <trace/events/sched.h>
 
 #include <asm/irq_regs.h>
 
@@ -832,10 +833,20 @@ static ktime_t tick_nohz_next_event(struct tick_sched *ts, int cpu)
 	u64 basemono, next_tick, delta, expires;
 	unsigned long basejiff;
 
+	if (need_resched())
+		trace_sched_nr(1);
+	else
+		trace_sched_nr(2);
+
 	basemono = get_jiffies_update(&basejiff);
 	ts->last_jiffies = basejiff;
 	ts->timer_expires_base = basemono;
 
+	if (need_resched())
+		trace_sched_nr(3);
+	else
+		trace_sched_nr(4);
+
 	/*
 	 * Keep the periodic tick, when RCU, architecture or irq_work
 	 * requests it.
@@ -849,6 +860,10 @@ static ktime_t tick_nohz_next_event(struct tick_sched *ts, int cpu)
 	if (rcu_needs_cpu() || arch_needs_cpu() ||
 	    irq_work_needs_cpu() || local_timer_softirq_pending()) {
 		next_tick = basemono + TICK_NSEC;
+		if (need_resched())
+			trace_sched_nr(5);
+		else
+			trace_sched_nr(6);
 	} else {
 		/*
 		 * Get the next pending timer. If high resolution
@@ -859,6 +874,10 @@ static ktime_t tick_nohz_next_event(struct tick_sched *ts, int cpu)
 		 */
 		next_tick = get_next_timer_interrupt(basejiff, basemono);
 		ts->next_timer = next_tick;
+		if (need_resched())
+			trace_sched_nr(7);
+		else
+			trace_sched_nr(8);
 	}
 
 	/* Make sure next_tick is never before basemono! */
@@ -880,6 +899,10 @@ static ktime_t tick_nohz_next_event(struct tick_sched *ts, int cpu)
 			goto out;
 		}
 	}
+	if (need_resched())
+		trace_sched_nr(9);
+	else
+		trace_sched_nr(10);
 
 	/*
 	 * If this CPU is the one which had the do_timer() duty last, we limit
@@ -891,12 +914,21 @@ static ktime_t tick_nohz_next_event(struct tick_sched *ts, int cpu)
 	    (tick_do_timer_cpu != TICK_DO_TIMER_NONE || !ts->do_timer_last))
 		delta = KTIME_MAX;
 
+	if (need_resched())
+		trace_sched_nr(11);
+	else
+		trace_sched_nr(12);
+
 	/* Calculate the next expiry time */
 	if (delta < (KTIME_MAX - basemono))
 		expires = basemono + delta;
 	else
 		expires = KTIME_MAX;
 
+	if (need_resched())
+		trace_sched_nr(13);
+	else
+		trace_sched_nr(14);
 	ts->timer_expires = min_t(u64, expires, next_tick);
 
 out:
@@ -980,6 +1012,10 @@ static void tick_nohz_stop_tick(struct tick_sched *ts, int cpu)
 		ts->tick_stopped = 1;
 		trace_tick_stop(1, TICK_DEP_MASK_NONE);
 	}
+//	if (need_resched())
+//		trace_sched_nr(11);
+//	else
+//		trace_sched_nr(12);
 
 	ts->next_tick = expires;
 
@@ -1157,6 +1193,11 @@ void tick_nohz_idle_stop_tick(void)
 	int cpu = smp_processor_id();
 	ktime_t expires;
 
+//	if (need_resched())
+//		trace_sched_nr(9);
+//	else
+//		trace_sched_nr(10);
+
 	/*
 	 * If tick_nohz_get_sleep_length() ran tick_nohz_next_event(), the
 	 * tick timer expiration time is known already.
@@ -1167,6 +1208,11 @@ void tick_nohz_idle_stop_tick(void)
 		expires = tick_nohz_next_event(ts, cpu);
 	else
 		return;
+//	if (need_resched())
+//		trace_sched_nr(11);
+//	else
+//		trace_sched_nr(12);
+
 
 	ts->idle_calls++;
 
@@ -1174,6 +1220,11 @@ void tick_nohz_idle_stop_tick(void)
 		int was_stopped = ts->tick_stopped;
 
 		tick_nohz_stop_tick(ts, cpu);
+//		if (need_resched())
+//			trace_sched_nr(13);
+//		else
+//			trace_sched_nr(14);
+
 
 		ts->idle_sleeps++;
 		ts->idle_expires = expires;
diff --git a/kernel/time/timer.c b/kernel/time/timer.c
index 1bafa2dd326c0..5fa81def34aa1 100644
--- a/kernel/time/timer.c
+++ b/kernel/time/timer.c
@@ -54,10 +54,12 @@
 
 #include "tick-internal.h"
 #include "timer_migration.h"
-
+#include <trace/events/sched.h>
+#include <trace/events/timer_migration.h>
 #define CREATE_TRACE_POINTS
 #include <trace/events/timer.h>
 
+
 __visible u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
 
 EXPORT_SYMBOL(jiffies_64);
@@ -2264,10 +2266,11 @@ static inline u64 __get_next_timer_interrupt(unsigned long basej, u64 basem,
 	 * event. See timer_use_tmigr() for detailed information.
 	 */
 	idle_is_possible = time_after(nextevt, basej + 1);
+	trace_tmigr_fetched(basem, tevt.local, tevt.global, idle ? *idle: -1, base_local->is_idle, idle_is_possible);
+
 	if (idle_is_possible)
 		timer_use_tmigr(basej, basem, &nextevt, idle,
 				base_local->is_idle, &tevt);
-
 	/*
 	 * We have a fresh next event. Check whether we can forward the
 	 * base.
@@ -2312,8 +2315,11 @@ static inline u64 __get_next_timer_interrupt(unsigned long basej, u64 basem,
 		 * When timer base was already marked idle, nothing will be
 		 * changed here.
 		 */
-		if (!base_local->is_idle && idle_is_possible)
+		if (!base_local->is_idle && idle_is_possible) {
+			//trace_sched_nr(-2);
 			tmigr_cpu_activate();
+		}
+		//trace_sched_nr(-1);
 	}
 
 	raw_spin_unlock(&base_global->lock);