From owner-svn-src-head@FreeBSD.ORG Wed Oct 8 16:23:00 2014 Return-Path: Delivered-To: svn-src-head@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 480D336D; Wed, 8 Oct 2014 16:23:00 +0000 (UTC) Received: from svn.freebsd.org (svn.freebsd.org [IPv6:2001:1900:2254:2068::e6a:0]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 33C507DC; Wed, 8 Oct 2014 16:23:00 +0000 (UTC) Received: from svn.freebsd.org ([127.0.1.70]) by svn.freebsd.org (8.14.9/8.14.9) with ESMTP id s98GN0un076375; Wed, 8 Oct 2014 16:23:00 GMT (envelope-from jhb@FreeBSD.org) Received: (from jhb@localhost) by svn.freebsd.org (8.14.9/8.14.9/Submit) id s98GMxdO076371; Wed, 8 Oct 2014 16:22:59 GMT (envelope-from jhb@FreeBSD.org) Message-Id: <201410081622.s98GMxdO076371@svn.freebsd.org> X-Authentication-Warning: svn.freebsd.org: jhb set sender to jhb@FreeBSD.org using -f From: John Baldwin Date: Wed, 8 Oct 2014 16:22:59 +0000 (UTC) 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 X-SVN-Group: head MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: svn-src-head@freebsd.org X-Mailman-Version: 2.1.18-1 Precedence: list List-Id: SVN commit messages for the src tree for head/-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 08 Oct 2014 16:23:00 -0000 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 = {}