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.

-- 
John Baldwin