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
To: freebsd-current@freebsd.org
Cc: AN , "ma...@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;
@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 IDFUNCTION: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
___
freebsd-current@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-current
To unsubscribe, send any mail to "freebsd-current-unsubscr...@freebsd.org"
Re: problem with [intr{swi4: clock (0)}]
On Wed, Mar 21, 2018 at 15:38 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:
>
> rebuilt world and kernel
> turned off Virtualbox ( did not load kernel module)
> turned off in BIOS network, audio
> installed disk from another similar machine, booted and it shows the exact
> same problem.
>
> Here is what I see in top:
> last pid: 56553; load averages: 0.09, 0.44, 0.26
> up 0+00:04:38 11:25:24
> 472 processes: 14 running, 418 sleeping, 40 waiting
> CPU 0: 0.0% user, 0.0% nice, 0.0% system, 27.5% interrupt, 72.5% idle
> CPU 1: 0.7% user, 0.0% nice, 0.0% system, 0.0% interrupt, 99.3% idle
> CPU 2: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
> CPU 3: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
> CPU 4: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
> CPU 5: 0.0% user, 0.0% nice, 0.7% system, 0.0% interrupt, 99.3% idle
> CPU 6: 0.8% user, 0.0% nice, 0.8% system, 0.0% interrupt, 98.5% idle
> CPU 7: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
> CPU 8: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
> CPU 9: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
> CPU 10: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
> CPU 11: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
> Mem: 1096M Active, 53M Inact, 300K Laundry, 568M Wired, 290M Buf, 14G Free
> Swap: 21G Total, 21G Free
>
>PID USERNAME PRI NICE SIZERES STATE C TIMEWCPU COMMAND
> 11 root 155 ki31 0K 192K CPU11 4:32 100.00%
> [idle{idle: cpu1}]
> 11 root 155 ki31 0K 192K CPU88 4:31 100.00%
> [idle{idle: cpu8}]
> 11 root 155 ki31 0K 192K CPU99 4:30 100.00%
> [idle{idle: cpu9}]
> 11 root 155 ki31 0K 192K CPU22 4:30 100.00%
> [idle{idle: cpu2}]
> 11 root 155 ki31 0K 192K CPU10 10 4:30 100.00%
> [idle{idle: cpu10}]
> 11 root 155 ki31 0K 192K CPU55 4:27 100.00%
> [idle{idle: cpu5}]
> 11 root 155 ki31 0K 192K RUN11 4:25 99.82%
> [idle{idle: cpu11}]
> 11 root 155 ki31 0K 192K CPU66 4:30 98.93%
> [idle{idle: cpu6}]
> 11 root 155 ki31 0K 192K CPU77 4:31 96.83%
> [idle{idle: cpu7}]
> 11 root 155 ki31 0K 192K CPU33 4:27 94.94%
> [idle{idle: cpu3}]
> 11 root 155 ki31 0K 192K CPU44 4:29 94.11%
> [idle{idle: cpu4}]
> 11 root 155 ki31 0K 192K RUN 0 3:45 71.60%
> [idle{idle: cpu0}]
> 12 root -60- 0K 656K CPU00 0:53 28.43%
> [intr{swi4: clock (0)}]
>
>
> 28.20% [intr{swi4: clock (0)}] - the process is using close to 30% cpu
> time.
>
> I have no idea what could be causing this, any advice would be
> appreciated. Thanks in advance.
>
> 12 root -60- 0K 656K WAIT0 1:27 28.80% [intr{swi4:
> clock (0)}]
>
> systat shows:
>
>1 usersLoad 0.20 0.16 0.18 Mar 21 11:35
> Mem usage: 11%Phy 1%Kmem
> Mem: KBREALVIRTUAL VN PAGER SWAP
> PAGER
> Tot Share TotShareFree in out in
> out
> Act 1357104 111928 4267688 193328 14176K count
> All 1357984 112656 4285556 211028 pages
> Proc:
> Interrupts
>r p d s w Csw Trp Sys Int Sof Flt 8 ioflt 996k
> total
>1 314 2.0 296 2213 133 1.0 155cow
> atkbd0 1
> 8 zfod 996k
> cpu0:timer
> 0.1%Sys 1.9%Intr 0.1%User 0.0%Nice 98.0%Idle ozfod68
> xhci0 259
> |||||||||| %ozfod
> ahci0 260
> + daefr 5 re0
> 261
> 4 dtbuf prcfr
> hdac0 262
> Namei Name-cache Dir-cache349771 desvn 21 totfr
> hdac1 280
> Callshits %hits % 3740 numvn react 4
> cpu6:timer
> 474 474 100 958 frevn pdwak 5
> cpu10:time
>456 pdpgs11
> cpu7:timer
> Disks ada0 pass0 intrn10
> cpu11:time
> KB/t 0.00 0.00 469596 wire 3
> cpu1:timer
> tps 0 0 1121780 act 2
> cpu8:timer
> MB/s 0.00 0.00 170492 inact 8
> cpu9:timer
> %busy 0 0
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;
@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 IDFUNCTION: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
___
freebsd-current@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-current
To unsubscribe, send any mail to "freebsd-current-unsubscr...@freebsd.org"
problem with [intr{swi4: clock (0)}]
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:
rebuilt world and kernel
turned off Virtualbox ( did not load kernel module)
turned off in BIOS network, audio
installed disk from another similar machine, booted and it shows the exact
same problem.
Here is what I see in top:
last pid: 56553; load averages: 0.09, 0.44, 0.26
up 0+00:04:38 11:25:24
472 processes: 14 running, 418 sleeping, 40 waiting
CPU 0: 0.0% user, 0.0% nice, 0.0% system, 27.5% interrupt, 72.5% idle
CPU 1: 0.7% user, 0.0% nice, 0.0% system, 0.0% interrupt, 99.3% idle
CPU 2: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
CPU 3: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
CPU 4: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
CPU 5: 0.0% user, 0.0% nice, 0.7% system, 0.0% interrupt, 99.3% idle
CPU 6: 0.8% user, 0.0% nice, 0.8% system, 0.0% interrupt, 98.5% idle
CPU 7: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
CPU 8: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
CPU 9: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
CPU 10: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
CPU 11: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
Mem: 1096M Active, 53M Inact, 300K Laundry, 568M Wired, 290M Buf, 14G Free
Swap: 21G Total, 21G Free
PID USERNAME PRI NICE SIZERES STATE C TIMEWCPU COMMAND
11 root 155 ki31 0K 192K CPU11 4:32 100.00%
[idle{idle: cpu1}]
11 root 155 ki31 0K 192K CPU88 4:31 100.00%
[idle{idle: cpu8}]
11 root 155 ki31 0K 192K CPU99 4:30 100.00%
[idle{idle: cpu9}]
11 root 155 ki31 0K 192K CPU22 4:30 100.00%
[idle{idle: cpu2}]
11 root 155 ki31 0K 192K CPU10 10 4:30 100.00%
[idle{idle: cpu10}]
11 root 155 ki31 0K 192K CPU55 4:27 100.00%
[idle{idle: cpu5}]
11 root 155 ki31 0K 192K RUN11 4:25 99.82%
[idle{idle: cpu11}]
11 root 155 ki31 0K 192K CPU66 4:30 98.93%
[idle{idle: cpu6}]
11 root 155 ki31 0K 192K CPU77 4:31 96.83%
[idle{idle: cpu7}]
11 root 155 ki31 0K 192K CPU33 4:27 94.94%
[idle{idle: cpu3}]
11 root 155 ki31 0K 192K CPU44 4:29 94.11%
[idle{idle: cpu4}]
11 root 155 ki31 0K 192K RUN 0 3:45 71.60%
[idle{idle: cpu0}]
12 root -60- 0K 656K CPU00 0:53 28.43%
[intr{swi4: clock (0)}]
28.20% [intr{swi4: clock (0)}] - the process is using close to 30% cpu
time.
I have no idea what could be causing this, any advice would be
appreciated. Thanks in advance.
12 root -60- 0K 656K WAIT0 1:27 28.80% [intr{swi4:
clock (0)}]
systat shows:
1 usersLoad 0.20 0.16 0.18 Mar 21 11:35
Mem usage: 11%Phy 1%Kmem
Mem: KBREALVIRTUAL VN PAGER SWAP
PAGER
Tot Share TotShareFree in out in
out
Act 1357104 111928 4267688 193328 14176K count
All 1357984 112656 4285556 211028 pages
Proc:
Interrupts
r p d s w Csw Trp Sys Int Sof Flt 8 ioflt 996k
total
1 314 2.0 296 2213 133 1.0 155cow
atkbd0 1
8 zfod 996k
cpu0:timer
0.1%Sys 1.9%Intr 0.1%User 0.0%Nice 98.0%Idle ozfod68
xhci0 259
|||||||||| %ozfod
ahci0 260
+ daefr 5 re0
261
4 dtbuf prcfr
hdac0 262
Namei Name-cache Dir-cache349771 desvn 21 totfr
hdac1 280
Callshits %hits % 3740 numvn react 4
cpu6:timer
474 474 100 958 frevn pdwak 5
cpu10:time
456 pdpgs11
cpu7:timer
Disks ada0 pass0 intrn10
cpu11:time
KB/t 0.00 0.00 469596 wire 3
cpu1:timer
tps 0 0 1121780 act 2
cpu8:timer
MB/s 0.00 0.00 170492 inact 8
cpu9:timer
%busy 0 0 300 laund 5
cpu4:timer
14516016 free 2
cpu2:timer
183472 buf 7
cpu5:timer
