Re: problem with [intr{swi4: clock (0)}]

Hi:


On Fri, 23 Mar 2018, John Baldwin wrote:

> Date: Fri, 23 Mar 2018 12:11:03 -0700
> From: John Baldwin <jhb_at_freebsd.org>
> To: freebsd-current_at_freebsd.org
> Cc: AN <andy_at_neu.net>, "markj_at_FreeBSD.org" <markj_at_freebsd.org>,
>     "<rstone_at_freebsd.org>" <rstone_at_freebsd.org>
> Subject: Re: problem with [intr{swi4: clock (0)}]
> 
> 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;
> 	_at_funcs[self->func] = count();
> }
>
> callout_execute:::callout-end
> {
> 	_at_functimes[self->func] = sum(timestamp - self->start);
> }
>
> END
> {
> 	printf("\n\nCallout function counts:\n");
> 	printa("%_at_8u %a\n", _at_funcs);
> 	printf("\nCallout function runtime:\n");
> 	printa("%_at_d %a\n", _at_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.
>
>

To John and others who responded thanks for your time.  I have to 
apologize though for wasting your spare cpu cycles.  It turns out the root 
cause was a malfunctioning USB keyboard with a stuck key.  Removed and 
replaced, now everything is working normally.  Thanks again and sorry 
for the noise.

Best regards,

Andy