Bug 226968 - IRQ storm on cpu0 timer when holding down key on USB keyboard
Summary: IRQ storm on cpu0 timer when holding down key on USB keyboard
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: usb (show other bugs)
Version: CURRENT
Hardware: Any Any
: --- Affects Some People
Assignee: freebsd-usb mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-03-27 09:32 UTC by Johannes Lundberg
Modified: 2020-02-21 09:00 UTC (History)
3 users (show)

See Also:


Attachments
Resolve timer issues (1.94 KB, patch)
2018-03-28 12:48 UTC, Hans Petter Selasky
no flags Details | Diff
Resolve timer issues (1.65 KB, patch)
2018-03-28 15:30 UTC, Hans Petter Selasky
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Johannes Lundberg 2018-03-27 09:32:19 UTC
I noticed this when playing a first person shooter with keyboard controls.
To verify, do the following:

Open a terminal window (I used xfce4-terminal)

Run 
$ systat -vmstat

On the USB keyboard, hold down some key like 'a'.
All is normal at this stage. 

Without releasing 'a', press and release another key, like 'b'.

See the irqs on cpu0:timer go up to several hundred thousand.

Release 'a' and it will go back to normal. 


USB debug information (hw.usb.xhci.debug=16) does not show abnormal amounts of interrupts.

With this bug, playing a fps-like game with keyboard controls is impossible since the whole game lags during irq storm.
Comment 1 Johannes Lundberg 2018-03-27 09:35:26 UTC
I should mention that I'm using a EVDEV enabled kernel. I have not tried this on a non-EVDEV kernel.
Comment 2 Johannes Lundberg 2018-03-27 09:39:17 UTC
Also, the laptop's built-in PS/2 keyboard does not show this behavior, only the external USB keyboard (tried two different keyboards).
Comment 3 Hans Petter Selasky freebsd_committer 2018-03-27 10:59:57 UTC
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)
Comment 4 Johannes Lundberg 2018-03-27 11:24:29 UTC
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.
Comment 5 Hans Petter Selasky freebsd_committer 2018-03-27 11:26:21 UTC
Can you try to identify the timer causing this?

--HPS
Comment 6 Johannes Lundberg 2018-03-27 20:28:46 UTC
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
Comment 7 Hans Petter Selasky freebsd_committer 2018-03-28 06:51:46 UTC
Can you try to trace the "sbt" argument passed to:

kernel`callout_reset_sbt_on                                      85

?

It might be some invalid timeout.

--HPS
Comment 8 Johannes Lundberg 2018-03-28 08:59:13 UTC
Do you have the magic dtrace command to do that?
Comment 9 Hans Petter Selasky freebsd_committer 2018-03-28 09:05:03 UTC
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();
}
Comment 10 Johannes Lundberg 2018-03-28 09:29:16 UTC
Thanks hps! 

I'm getting A LOT of these (exact):

  3  16003       callout_reset_sbt_on:entry callout_reset_sbt_on(0xfffff8009b58e908,987842410,0)
Comment 11 Hans Petter Selasky freebsd_committer 2018-03-28 09:32:32 UTC
Can you run the result through:

sort | uniq 

?
Comment 12 Johannes Lundberg 2018-03-28 09:35:44 UTC
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)
Comment 13 Hans Petter Selasky freebsd_committer 2018-03-28 09:37:56 UTC
Can you dump all arguments for callout reset sbt function and check if the ABSOLUTE time flag is set?

--HPS
Comment 14 Hans Petter Selasky freebsd_committer 2018-03-28 09:40:05 UTC
This one:

/sys/sys/callout.h:#define	C_ABSOLUTE		0x0200 /* event time is absolute. */
Comment 15 Johannes Lundberg 2018-03-28 09:46:41 UTC
  0  16003       callout_reset_sbt_on:entry callout_reset_sbt_on(0xfffffe004c67c248,346885676462073,0,ffffffff8053d810,fffffe004c679000,4294967295,0x200)
Comment 16 Johannes Lundberg 2018-03-28 09:48:57 UTC
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
Comment 17 Johannes Lundberg 2018-03-28 09:57:04 UTC
TCP noise because I'm on ssh. Besides from that the system is very idle.
Comment 18 Hans Petter Selasky freebsd_committer 2018-03-28 10:50:55 UTC
I see the problem now :-)
Comment 19 Hans Petter Selasky freebsd_committer 2018-03-28 11:35:38 UTC
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
Comment 20 Hans Petter Selasky freebsd_committer 2018-03-28 11:39:48 UTC
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
Comment 21 Hans Petter Selasky freebsd_committer 2018-03-28 11:42:25 UTC
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
Comment 22 Hans Petter Selasky freebsd_committer 2018-03-28 12:48:01 UTC
Created attachment 191904 [details]
Resolve timer issues

Hi,

Can you try this patch?

--HPS
Comment 23 Johannes Lundberg 2018-03-28 13:29:46 UTC
Yep the patch solved it! No more irq storms, or high irq rates at all.
Comment 24 Hans Petter Selasky freebsd_committer 2018-03-28 15:30:39 UTC
Created attachment 191908 [details]
Resolve timer issues

Hi, Can you also test this version? --HPS
Comment 25 Johannes Lundberg 2018-03-28 15:46:17 UTC
The new version also fixes the issue.
Comment 26 commit-hook freebsd_committer 2018-03-28 17:39:48 UTC
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
Comment 27 commit-hook freebsd_committer 2020-02-21 09:00:22 UTC
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