Skip site navigation (1)Skip section navigation (2) 
Date:      Wed, 8 Oct 2014 16:22:59 +0000 (UTC)
From:      John Baldwin <jhb@FreeBSD.org>
To:        src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org
Subject:   svn commit: r272757 - in head: sys/kern tools/sched
Message-ID:  <201410081622.s98GMxdO076371@svn.freebsd.org>
next in thread | raw e-mail | index | archive | help 
Author: jhb
Date: Wed Oct  8 16:22:59 2014
New Revision: 272757
URL: https://svnweb.freebsd.org/changeset/base/272757

Log:
  Add schedgraph traces for callout handlers.  Specifically, a callwheel logs
  a running event each time it executes a callout function.  The event
  includes the function pointer, argument, and whether or not it was run from
  hardware interrupt context.  The callwheel is marked idle when each handler
  completes.  This effectively logs the duration of each callout routine in
  the graph.

Modified:
  head/sys/kern/kern_timeout.c
  head/tools/sched/schedgraph.py

Modified: head/sys/kern/kern_timeout.c
==============================================================================
--- head/sys/kern/kern_timeout.c	Wed Oct  8 16:22:26 2014	(r272756)
+++ head/sys/kern/kern_timeout.c	Wed Oct  8 16:22:59 2014	(r272757)
@@ -163,6 +163,7 @@ struct callout_cpu {
 	sbintime_t		cc_lastscan;
 	void			*cc_cookie;
 	u_int			cc_bucket;
+	char			cc_ktr_event_name[20];
 };
 
 #define	cc_exec_curr		cc_exec_entity[0].cc_curr
@@ -201,7 +202,7 @@ struct callout_cpu cc_cpu;
 
 static int timeout_cpu;
 
-static void	callout_cpu_init(struct callout_cpu *cc);
+static void	callout_cpu_init(struct callout_cpu *cc, int cpu);
 static void	softclock_call_cc(struct callout *c, struct callout_cpu *cc,
 #ifdef CALLOUT_PROFILING
 		    int *mpcalls, int *lockcalls, int *gcalls,
@@ -302,7 +303,7 @@ callout_callwheel_init(void *dummy)
 	cc = CC_CPU(timeout_cpu);
 	cc->cc_callout = malloc(ncallout * sizeof(struct callout),
 	    M_CALLOUT, M_WAITOK);
-	callout_cpu_init(cc);
+	callout_cpu_init(cc, timeout_cpu);
 }
 SYSINIT(callwheel_init, SI_SUB_CPU, SI_ORDER_ANY, callout_callwheel_init, NULL);
 
@@ -310,7 +311,7 @@ SYSINIT(callwheel_init, SI_SUB_CPU, SI_O
  * Initialize the per-cpu callout structures.
  */
 static void
-callout_cpu_init(struct callout_cpu *cc)
+callout_cpu_init(struct callout_cpu *cc, int cpu)
 {
 	struct callout *c;
 	int i;
@@ -325,6 +326,8 @@ callout_cpu_init(struct callout_cpu *cc)
 	cc->cc_firstevent = SBT_MAX;
 	for (i = 0; i < 2; i++)
 		cc_cce_cleanup(cc, i);
+	snprintf(cc->cc_ktr_event_name, sizeof(cc->cc_ktr_event_name),
+	    "callwheel cpu %d", cpu);
 	if (cc->cc_callout == NULL)	/* Only cpu0 handles timeout(9) */
 		return;
 	for (i = 0; i < ncallout; i++) {
@@ -396,7 +399,7 @@ start_softclock(void *dummy)
 			continue;
 		cc = CC_CPU(cpu);
 		cc->cc_callout = NULL;	/* Only cpu0 handles timeout(9). */
-		callout_cpu_init(cc);
+		callout_cpu_init(cc, cpu);
 		snprintf(name, sizeof(name), "clock (%d)", cpu);
 		ie = NULL;
 		if (swi_add(&ie, name, softclock, cc, SWI_CLOCK,
@@ -711,6 +714,8 @@ softclock_call_cc(struct callout *c, str
 		CTR3(KTR_CALLOUT, "callout %p func %p arg %p",
 		    c, c_func, c_arg);
 	}
+	KTR_STATE3(KTR_SCHED, "callout", cc->cc_ktr_event_name, "running",
+	    "func:%p", c_func, "arg:%p", c_arg, "direct:%d", direct);
 #if defined(DIAGNOSTIC) || defined(CALLOUT_PROFILING)
 	sbt1 = sbinuptime();
 #endif
@@ -733,6 +738,7 @@ softclock_call_cc(struct callout *c, str
 		lastfunc = c_func;
 	}
 #endif
+	KTR_STATE0(KTR_SCHED, "callout", cc->cc_ktr_event_name, "idle");
 	CTR1(KTR_CALLOUT, "callout %p finished", c);
 	if ((c_flags & CALLOUT_RETURNUNLOCKED) == 0)
 		class->lc_unlock(c_lock);

Modified: head/tools/sched/schedgraph.py
==============================================================================
--- head/tools/sched/schedgraph.py	Wed Oct  8 16:22:26 2014	(r272756)
+++ head/tools/sched/schedgraph.py	Wed Oct  8 16:22:59 2014	(r272757)
@@ -80,8 +80,6 @@ eventcolors = [
 	("runq rem",	"yellow"),
 	("thread exit",	"grey"),
 	("proc exit",	"grey"),
-	("callwheel idle", "grey"),
-	("callout running", "green"),
 	("lock acquire", "blue"),
 	("lock contest", "purple"),
 	("failed lock try", "red"),
@@ -903,7 +901,6 @@ class KTRFile:
 		self.timestamp_f = None
 		self.timestamp_l = None
 		self.locks = {}
-		self.callwheels = {}
 		self.ticks = {}
 		self.load = {}
 		self.crit = {}

Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201410081622.s98GMxdO076371>