Bug 226968
| Summary: | IRQ storm on cpu0 timer when holding down key on USB keyboard | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | Base System | Reporter: | Johannes Lundberg <johalun0> | ||||||
| Component: | usb | Assignee: | freebsd-usb (Nobody) <usb> | ||||||
| Status: | Closed FIXED | ||||||||
| Severity: | Affects Some People | CC: | bde, hps, hselasky | ||||||
| Priority: | --- | ||||||||
| Version: | CURRENT | ||||||||
| Hardware: | Any | ||||||||
| OS: | Any | ||||||||
| Attachments: |
|
||||||||
|
Description
Johannes Lundberg
2018-03-27 09:32:19 UTC
I should mention that I'm using a EVDEV enabled kernel. I have not tried this on a non-EVDEV kernel. Also, the laptop's built-in PS/2 keyboard does not show this behavior, only the external USB keyboard (tried two different keyboards). Hi,
I have been discussing some patches with Bruce Evans on this topic. The problem is the keyboard repeat rate is zero, which cause the timer to trigger instantly. This issue fell off my radar. Here is the last patch WIP:
Index: sys/arm/samsung/exynos/chrome_kb.c
===================================================================
--- sys/arm/samsung/exynos/chrome_kb.c
+++ sys/arm/samsung/exynos/chrome_kb.c
@@ -514,17 +514,8 @@
if (!KBD_HAS_DEVICE(kbd)) {
return (0);
}
- if (((int *)arg)[1] < 0) {
- return (EINVAL);
- }
- if (((int *)arg)[0] < 0) {
- return (EINVAL);
- }
- if (((int *)arg)[0] < 200) /* fastest possible value */
- kbd->kb_delay1 = 200;
- else
- kbd->kb_delay1 = ((int *)arg)[0];
- kbd->kb_delay2 = ((int *)arg)[1];
+ kbd->kb_delay1 = KEYBOARD_REPEAT_GET(arg,0,200,1000);
+ kbd->kb_delay2 = KEYBOARD_REPEAT_GET(arg,1,34,504);
return (0);
case KDSETRAD: /* set keyboard repeat rate (old
Index: sys/arm/versatile/pl050.c
===================================================================
--- sys/arm/versatile/pl050.c
+++ sys/arm/versatile/pl050.c
@@ -418,17 +418,8 @@
if (!KBD_HAS_DEVICE(kbd)) {
return (0);
}
- if (((int *)arg)[1] < 0) {
- return (EINVAL);
- }
- if (((int *)arg)[0] < 0) {
- return (EINVAL);
- }
- if (((int *)arg)[0] < 200) /* fastest possible value */
- kbd->kb_delay1 = 200;
- else
- kbd->kb_delay1 = ((int *)arg)[0];
- kbd->kb_delay2 = ((int *)arg)[1];
+ kbd->kb_delay1 = KEYBOARD_REPEAT_GET(arg,0,200,1000);
+ kbd->kb_delay2 = KEYBOARD_REPEAT_GET(arg,1,34,504);
return (0);
#if defined(COMPAT_FREEBSD6) || defined(COMPAT_FREEBSD5) || \
Index: sys/dev/adb/adb_kbd.c
===================================================================
--- sys/dev/adb/adb_kbd.c
+++ sys/dev/adb/adb_kbd.c
@@ -780,16 +780,8 @@
case KDSETREPEAT:
if (!KBD_HAS_DEVICE(kbd))
return 0;
- if (((int *)data)[1] < 0)
- return EINVAL;
- if (((int *)data)[0] < 0)
- return EINVAL;
- else if (((int *)data)[0] == 0) /* fastest possible value */
- kbd->kb_delay1 = 200;
- else
- kbd->kb_delay1 = ((int *)data)[0];
- kbd->kb_delay2 = ((int *)data)[1];
-
+ kbd->kb_delay1 = KEYBOARD_REPEAT_GET(data,0,200,1000);
+ kbd->kb_delay2 = KEYBOARD_REPEAT_GET(data,1,34,504);
break;
case KDSETRAD:
Index: sys/dev/gpio/gpiokeys.c
===================================================================
--- sys/dev/gpio/gpiokeys.c
+++ sys/dev/gpio/gpiokeys.c
@@ -822,17 +822,8 @@
if (!KBD_HAS_DEVICE(kbd)) {
return (0);
}
- if (((int *)arg)[1] < 0) {
- return (EINVAL);
- }
- if (((int *)arg)[0] < 0) {
- return (EINVAL);
- }
- if (((int *)arg)[0] < 200) /* fastest possible value */
- kbd->kb_delay1 = 200;
- else
- kbd->kb_delay1 = ((int *)arg)[0];
- kbd->kb_delay2 = ((int *)arg)[1];
+ kbd->kb_delay1 = KEYBOARD_REPEAT_GET(arg,0,200,1000);
+ kbd->kb_delay2 = KEYBOARD_REPEAT_GET(arg,1,34,504);
return (0);
#if defined(COMPAT_FREEBSD6) || defined(COMPAT_FREEBSD5) || \
Index: sys/dev/usb/input/ukbd.c
===================================================================
--- sys/dev/usb/input/ukbd.c
+++ sys/dev/usb/input/ukbd.c
@@ -1946,14 +1946,8 @@
if (!KBD_HAS_DEVICE(kbd)) {
return (0);
}
- /*
- * Convert negative, zero and tiny args to the same limits
- * as atkbd. We could support delays of 1 msec, but
- * anything much shorter than the shortest atkbd value
- * of 250.34 is almost unusable as well as incompatible.
- */
- kbd->kb_delay1 = imax(((int *)arg)[0], 250);
- kbd->kb_delay2 = imax(((int *)arg)[1], 34);
+ kbd->kb_delay1 = KEYBOARD_REPEAT_GET(arg,0,200,1000);
+ kbd->kb_delay2 = KEYBOARD_REPEAT_GET(arg,1,34,504);
#ifdef EVDEV_SUPPORT
if (sc->sc_evdev != NULL)
evdev_push_repeats(sc->sc_evdev, kbd);
Index: sys/sys/kbio.h
===================================================================
--- sys/sys/kbio.h
+++ sys/sys/kbio.h
@@ -87,6 +87,15 @@
int kb_repeat[2];
};
typedef struct keyboard_repeat keyboard_repeat_t;
+
+#define KEYBOARD_REPEAT_GET(p,i,min,max) ({ \
+ const struct keyboard_repeat *__ptr = \
+ (const struct keyboard_repeat *)(p); \
+ __ptr->kb_repeat[i] < (min) ? (int)(min) : \
+ __ptr->kb_repeat[i] > (max) ? (int)(max) : \
+ __ptr->kb_repeat[i]; \
+})
+
#define KDSETREPEAT _IOW('K', 102, keyboard_repeat_t)
#define KDGETREPEAT _IOR('K', 103, keyboard_repeat_t)
Hi I tried a variant of this patch a few weeks ago and it did help a bit to reduce interrupts but the problem described in this report still remains, even with the patch you provided. Can you try to identify the timer causing this? --HPS Here output from
# dtrace -n 'profile-997hz /arg0/ { @[func(arg0)]=count(); }'
run for about 10 seconds for each state
First idle state
-- SNIP --
linux_common.ko`linux_kernver 1
linux.ko`linux_gettimeofday 1
linux.ko`linux_sendsig 1
kernel`ithread_loop 2
kernel`witness_checkorder 2
kernel`witness_warn 2
linux.ko`0xffffffff820c2f60 2
kernel`_isitmyx 3
kernel`witness_unlock 4
kernel`vt_fb_bitblt_bitmap 11
kernel`spinlock_exit 11
kernel`cpu_idle 37
kernel`acpi_cpu_idle 26778
And then with cpu0:timer firing at 800k/s
-- SNIP --
kernel`pagezero 1
linux.ko`0xffffffff820c2f60 1
kernel`vt_fb_bitblt_text 2
kernel`vt_fb_bitblt_bitmap 11
kernel`lock_mtx 16
kernel`lock_delay 21
kernel`unlock_mtx 31
kernel`cpu_idle 55
kernel`callout_when 57
kernel`witness_lock 77
kernel`callout_reset_sbt_on 85
kernel`spinlock_enter 99
kernel`__mtx_lock_spin_flags 103
kernel`softclock_call_cc 118
kernel`ukbd_timeout 119
kernel`witness_checkorder 150
kernel`__mtx_assert 155
kernel`usbd_in_polling_mode 167
kernel`__mtx_lock_flags 179
kernel`__mtx_unlock_flags 180
kernel`ukbd_interrupt 298
kernel`memcpy 313
kernel`witness_unlock 318
kernel`spinlock_exit 11745
kernel`acpi_cpu_idle 45519
And some procstat -ak during irq storm
root@jd2:/usr/home/johannes # procstat -ak|grep 100023
12 100023 intr swi4: clock (0) mi_switch ithread_loop fork_exit fork_trampoline
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) <running>
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) callout_reset_sbt_on ukbd_timeout softclock_call_cc softclock intr_event_execute_handlers ithread_loop fork_exit fork_trampoline
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) <running>
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) ukbd_timeout softclock_call_cc softclock intr_event_execute_handlers ithread_loop fork_exit fork_trampoline
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) <running>
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) ukbd_interrupt ukbd_timeout softclock_call_cc softclock intr_event_execute_handlers ithread_loop fork_exit fork_trampoline
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) callout_reset_sbt_on ukbd_timeout softclock_call_cc softclock intr_event_execute_handlers ithread_loop fork_exit fork_trampoline
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) callout_reset_sbt_on ukbd_timeout softclock_call_cc softclock intr_event_execute_handlers ithread_loop fork_exit fork_trampoline
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) <running>
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) callout_reset_sbt_on ukbd_timeout softclock_call_cc softclock intr_event_execute_handlers ithread_loop fork_exit fork_trampoline
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) softclock intr_event_execute_handlers ithread_loop fork_exit fork_trampoline
root@jd2:/usr/home/johannes # procstat -ak | grep 100023
12 100023 intr swi4: clock (0) ukbd_interrupt ukbd_timeout softclock_call_cc softclock intr_event_execute_handlers ithread_loop fork_exit fork_trampoline
Can you try to trace the "sbt" argument passed to: kernel`callout_reset_sbt_on 85 ? It might be some invalid timeout. --HPS Do you have the magic dtrace command to do that? When you make a hook for a function "$1", then you can print arg0, arg1, arg2 and so on. We're interested in arg1 I guess.
int callout_reset_sbt_on(struct callout *, sbintime_t, sbintime_t,
void (*)(void *), void *, int, int);
Try this:
#!/usr/sbin/dtrace -s
fbt::$1:entry
{
printf("callout_reset_sbt_on(%d,%d)\n", arg0, arg1);
@[probefunc, stack()] = count();
}
Thanks hps! I'm getting A LOT of these (exact): 3 16003 callout_reset_sbt_on:entry callout_reset_sbt_on(0xfffff8009b58e908,987842410,0) Can you run the result through: sort | uniq ? Maybe these are more interesting Subsequent runs give these. 0 16003 callout_reset_sbt_on:entry callout_reset_sbt_on(0xfffffe004c67c248,343308871394961,0) and the run after that give a lot of 0 16003 callout_reset_sbt_on:entry callout_reset_sbt_on(0xfffffe004c67c248,343697608936462,0) and the next run 0 16003 callout_reset_sbt_on:entry callout_reset_sbt_on(0xfffffe004c67c248,343959836760265,0) Can you dump all arguments for callout reset sbt function and check if the ABSOLUTE time flag is set? --HPS This one: /sys/sys/callout.h:#define C_ABSOLUTE 0x0200 /* event time is absolute. */ 0 16003 callout_reset_sbt_on:entry callout_reset_sbt_on(0xfffffe004c67c248,346885676462073,0,ffffffff8053d810,fffffe004c679000,4294967295,0x200) The top two (those with significant count):
callout_reset_sbt_on
kernel`tcp_timer_activate+0xfd
kernel`tcp_do_segment+0x1191
kernel`tcp_input+0xf1e
kernel`ip_input+0x3f7
kernel`netisr_dispatch_src+0xa2
kernel`ether_demux+0x16e
kernel`ether_nh_input+0x3cc
kernel`netisr_dispatch_src+0xa2
kernel`ether_input+0x8f
kernel`tcp_lro_flush+0x217
kernel`tcp_lro_flush_all+0x13b
kernel`_task_fn_rx+0xe27
kernel`gtaskqueue_run_locked+0x139
kernel`gtaskqueue_thread_loop+0x88
kernel`fork_exit+0x84
kernel`0xffffffff80a0d27e
37803
callout_reset_sbt_on
kernel`ukbd_timeout+0x153
kernel`softclock_call_cc+0x150
kernel`softclock+0x7c
kernel`intr_event_execute_handlers+0x99
kernel`ithread_loop+0xb7
kernel`fork_exit+0x84
kernel`0xffffffff80a0d27e
183378
TCP noise because I'm on ssh. Besides from that the system is very idle. I see the problem now :-) Hi Bruce,
The problem is that sc_delay is set to zero, but never setup again:
640 ukbd_timeout(void *arg)
641 {
642 struct ukbd_softc *sc = arg;
643
644 avg 228765 UKBD_LOCK_ASSERT();
645 alfred 184610
646 bde 304735 sc->sc_time_ms += sc->sc_delay;
647 sc->sc_delay = 0;
--HPS
Hi Bruce, I don't like the ABSOLUTE flag passed to callout_reset_sbt(). Can we change this logic to align the time, instead of incrementing it? --HPS Hi Bruce, There are two conditions which cause ukbd_start_timer() to be called: if (ukbd_any_key_pressed(sc) || (sc->sc_inputs != 0)) It looks like you've tested only when ukbd_any_key_pressed() is pressed. --HPS Created attachment 191904 [details]
Resolve timer issues
Hi,
Can you try this patch?
--HPS
Yep the patch solved it! No more irq storms, or high irq rates at all. Created attachment 191908 [details]
Resolve timer issues
Hi, Can you also test this version? --HPS
The new version also fixes the issue. A commit references this bug: Author: hselasky Date: Wed Mar 28 17:39:23 UTC 2018 New revision: 331692 URL: https://svnweb.freebsd.org/changeset/base/331692 Log: Fix for regression issue in USB keyboard driver after r304735. A series of zero delay callouts can happen causing high CPU usage of the timer subsystem when trying to repeat keys, because the time of the absolute timeout is not moving forward. The condition clears when all keys are released. Reported by: Johannes Lundberg <johalun0@gmail.com> Discussed with: bde@ PR: 226968 MFC after: 1 week Sponsored by: Mellanox Technologies Changes: head/sys/dev/usb/input/ukbd.c A commit references this bug: Author: hselasky Date: Fri Feb 21 08:59:21 UTC 2020 New revision: 358215 URL: https://svnweb.freebsd.org/changeset/base/358215 Log: MFC r304735 and r331692: Fix key delay and repeat, part 2. Use sbintime_t timeouts with precision control to get very accurate timing. It costs little to always ask for about 1% accuracy, and the not so new event timer implementation usual delivers that, and when it can't it gets much closer than our previous coarse timeouts and buggy simple countdown. The 2 fastest atkbd repeat rates have periods 34 and 38 msec, and ukbd pretended to support rates in between these. This requires sub-microsecond precision and accuracy even to handle the 4 msec difference very well, but ukbd asked the timeout subsystem for timeouts of 25 msec and the buggy simple countdown of this gave a a wide range of precisions and accuracies depending on HZ and other timer configuration (sometimes better than 25 msec but usually more like 50 msec). We now ask for and usually get precision and accuracy of about 1% for each repeat and much better on average. The 1% accuracy is overkill. Rounding of 30 cps to 34 msec instead of 33 already gives an error of +2% instead of -1%, and ut AT keyboards on PS/2 interfaces have similar errors. A timeout is now scheduled for every keypress and release. This allows some simplifications that are not done. It allows removing the timeout scheduling for exiting polled mode where it was unsafe in ddb mode. This is done. Exiting polled mode had some problems with extra repeats. Now exiting polled mode lets an extra timeout fire and the state is fudged so that the timeout handler does very little. The sc->time_ms variable is unsigned to avoid overflow. Differences of it need to be signed. Signed comparisons were emulated by testing an emulated sign bits. This only works easily for '<' comparisonss, but we now need a '<=' comparison. Change the difference variable to signed and use a signed comparison. Using unsigned types here didn't prevent overflow bugs but just reduced them. Overflow occurs with n repeats at the silly repeat period of [U]INT_MAX / n. The old countdown had an off by 1 error, and the simplifications would simply count down 1 to 0 and not need to accumulate possibly-large repeat repeats. PR: 226968 Sponsored by: Mellanox Technologies Changes: _U stable/11/ stable/11/sys/dev/usb/input/ukbd.c |
