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

Discussion:

(too old to reply)

2018-03-21 15:36:48 UTC

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 SIZE RES STATE C TIME WCPU COMMAND
11 root 155 ki31 0K 192K CPU1 1 4:32 100.00%
[idle{idle: cpu1}]
11 root 155 ki31 0K 192K CPU8 8 4:31 100.00%
[idle{idle: cpu8}]
11 root 155 ki31 0K 192K CPU9 9 4:30 100.00%
[idle{idle: cpu9}]
11 root 155 ki31 0K 192K CPU2 2 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 CPU5 5 4:27 100.00%
[idle{idle: cpu5}]
11 root 155 ki31 0K 192K RUN 11 4:25 99.82%
[idle{idle: cpu11}]
11 root 155 ki31 0K 192K CPU6 6 4:30 98.93%
[idle{idle: cpu6}]
11 root 155 ki31 0K 192K CPU7 7 4:31 96.83%
[idle{idle: cpu7}]
11 root 155 ki31 0K 192K CPU3 3 4:27 94.94%
[idle{idle: cpu3}]
11 root 155 ki31 0K 192K CPU4 4 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 CPU0 0 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 WAIT 0 1:27 28.80% [intr{swi4:
clock (0)}]

systat shows:

1 users Load 0.20 0.16 0.18 Mar 21 11:35
Mem usage: 11%Phy 1%Kmem
Mem: KB REAL VIRTUAL VN PAGER SWAP
PAGER
Tot Share Tot Share Free 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 155 cow
atkbd0 1
8 zfod 996k
cpu0:timer
0.1%Sys 1.9%Intr 0.1%User 0.0%Nice 98.0%Idle ozfod 68
xhci0 259
| | | | | | | | | | %ozfod
ahci0 260
+ daefr 5 re0
261
4 dtbuf prcfr
hdac0 262
Namei Name-cache Dir-cache 349771 desvn 21 totfr
hdac1 280
Calls hits % hits % 3740 numvn react 4
cpu6:timer
474 474 100 958 frevn pdwak 5
cpu10:time
456 pdpgs 11
cpu7:timer
Disks ada0 pass0 intrn 10
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
7
cpu3:timer

FreeBSD BSD_12 12.0-CURRENT FreeBSD 12.0-CURRENT #18 r331138: Sun Mar 18
16:08:31 EDT 2018
***@BSD_12:/usr/obj/usr/src/amd64.amd64/sys/MYKERNEL amd64 1200060

FreeBSD 12.0-CURRENT #18 r331138: Sun Mar 18 16:08:31 EDT 2018
***@BSD_12:/usr/obj/usr/src/amd64.amd64/sys/MYKERNEL amd64
FreeBSD clang version 6.0.0 (tags/RELEASE_600/final 326565) (based on LLVM
6.0.0)
VT(vga): resolution 640x480
CPU: AMD Ryzen 5 1600X Six-Core Processor (3600.10-MHz K8-class
CPU)
Origin="AuthenticAMD" Id=0x800f11 Family=0x17 Model=0x1 Stepping=1

Features=0x178bfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,MMX,FXSR,SSE,SSE2,HTT>

Features2=0x7ed8320b<SSE3,PCLMULQDQ,MON,SSSE3,FMA,CX16,SSE4.1,SSE4.2,MOVBE,POPCNT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND>
AMD Features=0x2e500800<SYSCALL,NX,MMX+,FFXSR,Page1GB,RDTSCP,LM>
AMD
Features2=0x35c233ff<LAHF,CMP,SVM,ExtAPIC,CR8,ABM,SSE4A,MAS,Prefetch,OSVW,SKINIT,WDT,TCE,Topology,PCXC,PNXC,DBE,PL2I,MWAITX>
Structured Extended
Features=0x209c01a9<FSGSBASE,BMI1,AVX2,SMEP,BMI2,RDSEED,ADX,SMAP,CLFLUSHOPT,SHA>
XSAVE Features=0xf<XSAVEOPT,XSAVEC,XINUSE,XSAVES>
AMD Extended Feature Extensions ID EBX=0x7<CLZERO,IRPerf,XSaveErPtr>
SVM: NP,NRIP,VClean,AFlush,DAssist,NAsids=32768
TSC: P-state invariant, performance statistics
real memory = 17179869184 (16384 MB)
avail memory = 16596353024 (15827 MB)
Event timer "LAPIC" quality 600
ACPI APIC Table: <ALASKA A M I >
FreeBSD/SMP: Multiprocessor System Detected: 12 CPUs
FreeBSD/SMP: 1 package(s) x 2 cache groups x 3 core(s) x 2 hardware
threads
random: unblocking device.
Firmware Warning (ACPI): Optional FADT field Pm2ControlBlock has valid
Length but zero Address: 0x0000000000000000/0x1 (20180313/tbfadt-796)
ioapic0 <Version 2.1> irqs 0-23 on motherboard
ioapic1 <Version 2.1> irqs 24-55 on motherboard
random: entropy device external interface
kbd1 at kbdmux0
netmap: loaded module
module_register_init: MOD_LOAD (vesa, 0xffffffff809e79e0, 0) error 19
random: registering fast source Intel Secure Key RNG
random: fast provider: "Intel Secure Key RNG"
nexus0
vtvga0: <VT VGA driver> on motherboard
cryptosoft0: <software crypto> on motherboard
acpi0: <ALASKA A M I > on motherboard

John Baldwin

2018-03-23 19:11:03 UTC

Permalink

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

2018-03-25 18:36:23 UTC

Permalink

Date: Fri, 23 Mar 2018 12:11:03 -0700
Subject: Re: problem with [intr{swi4: clock (0)}]

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
----
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");
printf("\nCallout function runtime:\n");
}
----
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
CPU ID FUNCTION:NAME
4 2 :END
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
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

Johannes Lundberg

2018-03-23 19:48:15 UTC

Permalink

Post by AN
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
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.
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 SIZE RES STATE C TIME WCPU COMMAND
11 root 155 ki31 0K 192K CPU1 1 4:32 100.00%
[idle{idle: cpu1}]
11 root 155 ki31 0K 192K CPU8 8 4:31 100.00%
[idle{idle: cpu8}]
11 root 155 ki31 0K 192K CPU9 9 4:30 100.00%
[idle{idle: cpu9}]
11 root 155 ki31 0K 192K CPU2 2 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 CPU5 5 4:27 100.00%
[idle{idle: cpu5}]
11 root 155 ki31 0K 192K RUN 11 4:25 99.82%
[idle{idle: cpu11}]
11 root 155 ki31 0K 192K CPU6 6 4:30 98.93%
[idle{idle: cpu6}]
11 root 155 ki31 0K 192K CPU7 7 4:31 96.83%
[idle{idle: cpu7}]
11 root 155 ki31 0K 192K CPU3 3 4:27 94.94%
[idle{idle: cpu3}]
11 root 155 ki31 0K 192K CPU4 4 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 CPU0 0 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.
clock (0)}]
1 users Load 0.20 0.16 0.18 Mar 21 11:35
Mem usage: 11%Phy 1%Kmem
Mem: KB REAL VIRTUAL VN PAGER SWAP
PAGER
Tot Share Tot Share Free in out in
out
Act 1357104 111928 4267688 193328 14176K count
All 1357984 112656 4285556 211028 pages
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 155 cow
atkbd0 1
8 zfod 996k
cpu0:timer
0.1%Sys 1.9%Intr 0.1%User 0.0%Nice 98.0%Idle ozfod 68
xhci0 259
| | | | | | | | | | %ozfod
ahci0 260
+ daefr 5 re0
261
4 dtbuf prcfr
hdac0 262
Namei Name-cache Dir-cache 349771 desvn 21 totfr
hdac1 280
Calls hits % hits % 3740 numvn react 4
cpu6:timer
474 474 100 958 frevn pdwak 5
cpu10:time
456 pdpgs 11
cpu7:timer
Disks ada0 pass0 intrn 10
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
7
cpu3:timer
FreeBSD BSD_12 12.0-CURRENT FreeBSD 12.0-CURRENT #18 r331138: Sun Mar 18
16:08:31 EDT 2018
FreeBSD 12.0-CURRENT #18 r331138: Sun Mar 18 16:08:31 EDT 2018
FreeBSD clang version 6.0.0 (tags/RELEASE_600/final 326565) (based on LLVM
6.0.0)
VT(vga): resolution 640x480
CPU: AMD Ryzen 5 1600X Six-Core Processor (3600.10-MHz K8-class
CPU)
Origin="AuthenticAMD" Id=0x800f11 Family=0x17 Model=0x1 Stepping=1
Features=0x178bfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,MMX,FXSR,SSE,SSE2,HTT>
Features2=0x7ed8320b<SSE3,PCLMULQDQ,MON,SSSE3,FMA,CX16,SSE4.1,SSE4.2,MOVBE,POPCNT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND>
AMD Features=0x2e500800<SYSCALL,NX,MMX+,FFXSR,Page1GB,RDTSCP,LM>
AMD
Features2=0x35c233ff<LAHF,CMP,SVM,ExtAPIC,CR8,ABM,SSE4A,MAS,Prefetch,OSVW,SKINIT,WDT,TCE,Topology,PCXC,PNXC,DBE,PL2I,MWAITX>
Structured Extended
Features=0x209c01a9<FSGSBASE,BMI1,AVX2,SMEP,BMI2,RDSEED,ADX,SMAP,CLFLUSHOPT,SHA>
XSAVE Features=0xf<XSAVEOPT,XSAVEC,XINUSE,XSAVES>
AMD Extended Feature Extensions ID EBX=0x7<CLZERO,IRPerf,XSaveErPtr>
SVM: NP,NRIP,VClean,AFlush,DAssist,NAsids=32768
TSC: P-state invariant, performance statistics
real memory = 17179869184 (16384 MB)
avail memory = 16596353024 (15827 MB)
Event timer "LAPIC" quality 600
ACPI APIC Table: <ALASKA A M I >
FreeBSD/SMP: Multiprocessor System Detected: 12 CPUs
FreeBSD/SMP: 1 package(s) x 2 cache groups x 3 core(s) x 2 hardware
threads
random: unblocking device.
Firmware Warning (ACPI): Optional FADT field Pm2ControlBlock has valid
Length but zero Address: 0x0000000000000000/0x1 (20180313/tbfadt-796)
ioapic0 <Version 2.1> irqs 0-23 on motherboard
ioapic1 <Version 2.1> irqs 24-55 on motherboard
random: entropy device external interface
kbd1 at kbdmux0
netmap: loaded module
module_register_init: MOD_LOAD (vesa, 0xffffffff809e79e0, 0) error 19
random: registering fast source Intel Secure Key RNG
random: fast provider: "Intel Secure Key RNG"
nexus0
vtvga0: <VT VGA driver> on motherboard
cryptosoft0: <software crypto> on motherboard
acpi0: <ALASKA A M I > on motherboard

Hi!

I had a similar problem caused by interrupt storm from the GPU on a
MacBook.

The problem is described here:
https://bugs.freedesktop.org/show_bug.cgi?id=98501

I disabled that IRQ by using a custom acpi config. I know it’s not the same
hardware but might give

I can share more details tomorrow when I’m at my computer if you think this
might be related.

Post by AN
_______________________________________________
https://lists.freebsd.org/mailman/listinfo/freebsd-current