From owner-freebsd-current@freebsd.org Fri Mar 23 19:11:48 2018 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id BE684F65A64 for ; Fri, 23 Mar 2018 19:11:48 +0000 (UTC) (envelope-from jhb@freebsd.org) Received: from mail.baldwin.cx (bigwig.baldwin.cx [96.47.65.170]) (using TLSv1 with cipher DHE-RSA-CAMELLIA256-SHA (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 72E9387022; Fri, 23 Mar 2018 19:11:48 +0000 (UTC) (envelope-from jhb@freebsd.org) Received: from ralph.baldwin.cx (ralph.baldwin.cx [66.234.199.215]) by mail.baldwin.cx (Postfix) with ESMTPSA id 22C7D10A7DB; Fri, 23 Mar 2018 15:11:47 -0400 (EDT) From: John Baldwin To: freebsd-current@freebsd.org Cc: AN , "markj@FreeBSD.org" , "" Subject: Re: problem with [intr{swi4: clock (0)}] Date: Fri, 23 Mar 2018 12:11:03 -0700 Message-ID: <1901802.BMbLzLVd8F@ralph.baldwin.cx> User-Agent: KMail/4.14.10 (FreeBSD/11.1-STABLE; KDE/4.14.30; amd64; ; ) In-Reply-To: References: MIME-Version: 1.0 Content-Transfer-Encoding: 7Bit Content-Type: text/plain; charset="us-ascii" X-Greylist: Sender succeeded SMTP AUTH, not delayed by milter-greylist-4.4.3 (mail.baldwin.cx); Fri, 23 Mar 2018 15:11:47 -0400 (EDT) X-Virus-Scanned: clamav-milter 0.99.2 at mail.baldwin.cx X-Virus-Status: Clean X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.25 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 23 Mar 2018 19:11:49 -0000 On Wednesday, March 21, 2018 11:36:48 AM AN wrote: > Hi: > > I would appreciate any help with this issue, this is a new machine built > in the last week and if it is a hardware issue I want to return it. The > problem seems to have started in the last 24 hours or so. I am seeing a > really high cpu utilization for [intr{swi4: clock (0)}]. I have tried a > couple things to troubleshoot: I would try using dtrace to figure out which functions are running in the callout thread. I've cc'd a couple of folks in case they already have dtrace scripts to do this. You would probably want a script that watched callout_execute::callout-start and callout_execute::callout-end events. You would want to save the start time in callout-start and then report a delta along with the values of 'c->c_func' (the last argument to these probes is 'c'). You might be able to just store the time delta in an aggregate that is keyed on the function. Actually, I've gone ahead and written a little script: ---- callout_execute:::callout-start { self->start = timestamp; self->func = args[0]->c_func; @funcs[self->func] = count(); } callout_execute:::callout-end { @functimes[self->func] = sum(timestamp - self->start); } END { printf("\n\nCallout function counts:\n"); printa("%@8u %a\n", @funcs); printf("\nCallout function runtime:\n"); printa("%@d %a\n", @functimes); } ---- Store this in a file named 'callout.d' and then run 'dtrace -s callout.d'. Let it run for a second or two and then use Ctrl-C to stop it. The first table it will output is a histogram showing how many times different functions were invoked. The second table will count how much total time was spent in each function: CPU ID FUNCTION:NAME 4 2 :END Callout function counts: 2 kernel`kbdmux_kbd_intr_timo 2 kernel`usb_power_wdog 2 kernel`ipport_tick 2 kernel`tcp_timer_delack 2 kernel`nd6_timer 2 kernel`key_timehandler 2 dtrace.ko`dtrace_state_deadman 4 kernel`newnfs_timer 4 kernel`pfslowtimo 10 kernel`logtimeout 10 kernel`pffasttimo 18 kernel`lim_cb 32 kernel`iflib_timer 84 kernel`sleepq_timeout 224 dtrace.ko`dtrace_state_clean Callout function runtime: 2080 kernel`logtimeout 2198 kernel`kbdmux_kbd_intr_timo 2890 kernel`ipport_tick 3550 kernel`iflib_timer 3672 kernel`lim_cb 3936 kernel`pffasttimo 4023 dtrace.ko`dtrace_state_clean 4224 kernel`newnfs_timer 4751 kernel`key_timehandler 5286 kernel`nd6_timer 6700 kernel`usb_power_wdog 7341 kernel`pfslowtimo 19607 kernel`tcp_timer_delack 20273 dtrace.ko`dtrace_state_deadman 32262 kernel`sleepq_timeout You can use this to figure out which timer events are using CPU in the softclock thread/process. -- John Baldwin