Periodical interrupt storm when playing game with USB keyboard

Discussion:

(too old to reply)

Johannes Lundberg

2018-01-21 15:41:40 UTC

Hi

Finally I found the root to the problem that's been having me puzzled for
the last week.

I started playing UT2004 on my laptop while away from home. Worked
perfectly. When I'm home and connect external display+mouse/keyboard, I get
weird random lag.

It is intr process that goes up to 100% CPU usage (swi4: clock) for a
couple of seconds every 30 seconds or so, but only when I'm moving around
in the game. To move around you need to hold down any of the wasd-keys.

Turns out, the interrupt storms only happen when I use my external
keyboard, not with the laptop keyboard.

The internal keyboard is:
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0

and external (Microsoft sculpt ergonomic desktop):
ugen0.2: <Microsoft Microsoft 2.4GHz Transceiver v9.0> at usbus0
ukbd0: <Microsoft Microsoft 2.4GHz Transceiver v9.0, class 0/0, rev
2.00/7.97, addr 1> on usbus0

The game runs with a linux binary. 32/64bit both act the same.
It uses libSDL-1.2 from /compat/linux/lib for rendering but not sure about
input events.

I tried lowering the key repeat rate both with xset and kbdcontrol but it
has no effect.

I don't have any wired USB keyboard to try with.

Anyone have a clue to what's going on?

Hardware is Dell Latitude E7270
with
FreeBSD 12-CURRENT
drm-next-kmod
linux-c6

Hans Petter Selasky

2018-01-21 19:34:59 UTC

Permalink

Post by Johannes Lundberg
Hi
Finally I found the root to the problem that's been having me puzzled for
the last week.
I started playing UT2004 on my laptop while away from home. Worked
perfectly. When I'm home and connect external display+mouse/keyboard, I get
weird random lag.
It is intr process that goes up to 100% CPU usage (swi4: clock) for a
couple of seconds every 30 seconds or so, but only when I'm moving around
in the game. To move around you need to hold down any of the wasd-keys.
Turns out, the interrupt storms only happen when I use my external
keyboard, not with the laptop keyboard.
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
ugen0.2: <Microsoft Microsoft 2.4GHz Transceiver v9.0> at usbus0
ukbd0: <Microsoft Microsoft 2.4GHz Transceiver v9.0, class 0/0, rev
2.00/7.97, addr 1> on usbus0
The game runs with a linux binary. 32/64bit both act the same.
It uses libSDL-1.2 from /compat/linux/lib for rendering but not sure about
input events.
I tried lowering the key repeat rate both with xset and kbdcontrol but it
has no effect.
I don't have any wired USB keyboard to try with.
Anyone have a clue to what's going on?
Hardware is Dell Latitude E7270
with
FreeBSD 12-CURRENT
drm-next-kmod
linux-c6

Hi,

What does "vmstat -i" say?

The issue can also be caused by a timer with a small or zero timeout.

This can be checked by setting:
kern.eventtimer.periodic=1

in /boot/loader.conf and rebooting.

--HPS

Johannes Lundberg

2018-01-21 20:45:01 UTC

Permalink

Sending the same again, this time cc the list.

Post by Hans Petter Selasky

Hi,
What does "vmstat -i" say?

Don’t remember the exact values now but it says cpu0:timer is getting A
LOT of interrupts. Like at least 10-50x the others. Otherwise normal.

Post by Hans Petter Selasky
The issue can also be caused by a timer with a small or zero timeout.
kern.eventtimer.periodic=1
in /boot/loader.conf and rebooting.

Wow, kern.eventtimer.periodic=1 really made all the difference.
No problem at all now and all cpu timers have equal interrupt total and
rate.
What does kern.eventtimer.periodic do? The sysctl description wasn't
that elaborate...

Replying myself. Found some explanation at
https://www.freebsd.org/cgi/man.cgi?query=eventtimers&apropos=0&sektion=0&manpath=FreeBSD+12-current&arch=default&format=html

With periodic each cpu timer has an interrupt rate of 1999 while on one
shot it's around 700.
Maybe not a very power efficient and precise solution to the problem but it
works.

Post by Hans Petter Selasky
--HPS

Hans Petter Selasky

2018-01-21 21:07:39 UTC

Permalink

What does kern.eventtimer.periodic do? The sysctl description wasn't
that elaborate...

It turns off re-programming the timer every time there is a new callout
with earlier completion time.

--HPS

Ian Lepore

2018-01-21 21:22:05 UTC

Permalink

Post by Hans Petter Selasky

What does kern.eventtimer.periodic do? The sysctl description
wasn't
that elaborate...

It turns off re-programming the timer every time there is a new
callout
with earlier completion time.
--HPS

Well, it does more than that. It makes the system run "the old way"
where there are periodic timer interrupts that happen whether they need
to or not (bad for power saving), and there's no way to schedule
anything to happen on intervals other than when the periodic ticks
occur (so if kern.hz = 1000 and you ask to sleep for a microsecond you
may actually sleep up to a millisecond).

-- Ian

Johannes Lundberg

2018-01-21 22:57:20 UTC

Permalink

Post by Hans Petter Selasky

What does kern.eventtimer.periodic do? The sysctl description wasn't
that elaborate...

It turns off re-programming the timer every time there is a new callout
with earlier completion time.
--HPS

Thanks for the further explanation.
I curious as to where the problem might be though.. It is the game's
binary-only Linux executable (Unreal Engine 2.5), Linux SDL 1.2, or on the
FreeBSD side? Haven't experienced anything similar with Quake3...
Switching to periodic timer feels like overkill but it does the job as a
work around.

-- Ian

Johannes Lundberg

2018-01-22 09:54:11 UTC

Permalink

Post by Johannes Lundberg
Thanks for the further explanation.
I curious as to where the problem might be though.. It is the game's
binary-only Linux executable (Unreal Engine 2.5), Linux SDL 1.2, or on the
FreeBSD side? Haven't experienced anything similar with Quake3...
Switching to periodic timer feels like overkill but it does the job as a
work around.

Hi,
It might be simply this, that the wrong clock-type is used when setting up
absolute timeouts.

Actually I think the same thing happens on the Macbook (with MacOS) which
has a USB internal keyboard.
The Mac binary is probably the same code base as the Linux one. Running
Windows binary with wine does not experience this problem, unfortunately
wine can only launch this game on MacOS, not FreeBSD.

I assume USB can generate higher rate of interrupts than a PS/2 which this
game (*nix version) was probably designed for initially.

--HPS

blubee blubeeme

2018-01-23 02:33:57 UTC

Permalink

Hi
Yeah the timers eventually get coalesced unless someone's asking for a
ridciulously accurate timer value.
So is some driver asking for hyper-accurate callout timer that isn't
being coalesced? hps, is there any useful debugging to try and find
callouts that are requesting stupidly accurate timers? Maybe a dtrace
probe on the callout schedule entry point?
-adrian
_______________________________________________
https://lists.freebsd.org/mailman/listinfo/freebsd-current

I'd say dtrace might be able to get you in the right direction very quickly.

I used SDL in the past for android apps and the code is very Linux
specific. I am sure there's some Linux related timers in there somewhere
that FreeBSD is returning nothing from and that's what's killing the
performance.

I can almost guarantee that none of the SDL designers and or programmers
use any *BSD systems.

The easiest solution would be to go look at the timer code and implement
something that FreeBSD can work with and try to get that upstream.

These are just a few of the issues that will crop up when devs try to just
use shims to hook into the Linux kernel. Do the design work up front and
implement things in a native way or enjoy the jank.

DTrace should be able to point you in the right direction relatively
quickly.
The DTraceBook:
https://www.amazon.com/DTrace-Dynamic-Tracing-Solaris-FreeBSD/dp/0132091518

Best

Johannes Lundberg

2018-01-23 11:27:28 UTC

Permalink

Hi all

Some quick dtracing with play causing lag, vs play not causing lag (that is
not hold down any key on a usb keyboard for too long).

# dtrace -n 'profile-997hz /arg0/ { @[func(arg0)]=count(); }'

Lag version
-- snip --
linuxkpi.ko`idr_find 7
kernel`nanotime 8
kernel`__cap_rights_init 8
kernel`amd64_syscall 8
i915kms.ko`i915_gem_obj_lookup_or_create_vma 8
kernel`selfdfree 9
kernel`feed_matrix_S16LE 11
kernel`callout_lock 11
kernel`uma_zalloc_arg 11
kernel`z_feed_linear_S16LE 12
kernel`0xffffffff80f6877e 12
kernel`copyin 12
kernel`tsc_get_timecount_low_lfence 12
kernel`bzero 13
kernel`fget_unlocked 14
i915kms.ko`gen8_ppgtt_insert_pte_entries 14
kernel`callout_when 16
kernel`0xffffffff80f68fbc 26
kernel`kern_select 32
kernel`lock_mtx 50
kernel`spinlock_enter 53
kernel`bcopy 57
kernel`unlock_mtx 104
i915kms.ko`fw_domains_get 113

* kernel`ukbd_timeout 126
kernel`callout_reset_sbt_on 128
kernel`ukbd_interrupt 136*
* kernel`softclock_call_cc 192*
kernel`memcpy 284
kernel`cpu_idle 4257

* kernel`spinlock_exit 4312
kernel`lock_delay 11921*
kernel`acpi_cpu_idle 15265

No lag version
-- snip --
kernel`free 19
kernel`copyout 20
kernel`copyin 20
linuxkpi.ko`idr_find 21
kernel`selfdfree 24
kernel`tsc_get_timecount_low_lfence 25
kernel`__mtx_lock_flags 28
kernel`uma_zalloc_arg 30
kernel`bzero 31
i915kms.ko`gen8_ppgtt_insert_entries 31
drm.ko`drm_ioctl 32
kernel`fget_unlocked 36
kernel`amd64_syscall 37
kernel`kern_select 49
i915kms.ko`gen8_ppgtt_insert_pte_entries 61
kernel`0xffffffff80f68fbc 78
kernel`bcopy 90
i915kms.ko`fw_domains_get 228
kernel`spinlock_exit 284
kernel`cpu_idle 4698
kernel`acpi_cpu_idle 36288

I also tried rebuilding linux-c6_sdl-1.2 using get time functions in librt
vs libc but no difference.
Will dig deeper next time I have free time to spare.

Post by blubee blubeeme

I'd say dtrace might be able to get you in the right direction very quickly.
I used SDL in the past for android apps and the code is very Linux
specific. I am sure there's some Linux related timers in there somewhere
that FreeBSD is returning nothing from and that's what's killing the
performance.
I can almost guarantee that none of the SDL designers and or programmers
use any *BSD systems.
The easiest solution would be to go look at the timer code and implement
something that FreeBSD can work with and try to get that upstream.
These are just a few of the issues that will crop up when devs try to just
use shims to hook into the Linux kernel. Do the design work up front and
implement things in a native way or enjoy the jank.
DTrace should be able to point you in the right direction relatively
quickly.
The DTraceBook: https://www.amazon.com/DTrace-Dynamic-
Tracing-Solaris-FreeBSD/dp/0132091518
Best

blubee blubeeme

2018-01-23 12:06:24 UTC

Permalink

Post by Johannes Lundberg
Hi all
Some quick dtracing with play causing lag, vs play not causing lag (that
is not hold down any key on a usb keyboard for too long).
Lag version
-- snip --
linuxkpi.ko`idr_find 7
kernel`nanotime 8
kernel`__cap_rights_init 8
kernel`amd64_syscall 8
i915kms.ko`i915_gem_obj_lookup_or_create_vma 8
kernel`selfdfree 9
kernel`feed_matrix_S16LE 11
kernel`callout_lock 11
kernel`uma_zalloc_arg 11
kernel`z_feed_linear_S16LE 12
kernel`0xffffffff80f6877e 12
kernel`copyin 12
kernel`tsc_get_timecount_low_lfence 12
kernel`bzero 13
kernel`fget_unlocked 14
i915kms.ko`gen8_ppgtt_insert_pte_entries 14
kernel`callout_when 16
kernel`0xffffffff80f68fbc 26
kernel`kern_select 32
kernel`lock_mtx 50
kernel`spinlock_enter 53
kernel`bcopy 57
kernel`unlock_mtx 104
i915kms.ko`fw_domains_get 113
* kernel`ukbd_timeout 126
kernel`callout_reset_sbt_on 128
kernel`ukbd_interrupt 136*
* kernel`softclock_call_cc 192*
kernel`memcpy 284
kernel`cpu_idle 4257
* kernel`spinlock_exit 4312
kernel`lock_delay 11921*
kernel`acpi_cpu_idle 15265

A question on the mailing list about spinlocks and high cpu time:
https://lists.freebsd.org/pipermail/freebsd-questions/2008-October/183943.html

Although I think that for USB you can most likely fully replace the
spinlock with a lock free queue, stack allocator and a ring buffer.

Tony Van Eerd has been doing some very interesting work on lock free queue
and refined his implementation, his talk from this year's cpp con looks
very promising. You can check it out here:

Locks just have overhead that can't be avoided, with something like USB you
can use a heap allocator, a ring buffer and a lock free queue and that
should be able to get rid of the lock.

I remember looking at the USB stack a while ago, there's one global lock or
something like that and looking at the DTrace logs it's definitely that
causing issues somehwere.

It'll need testing though.

Post by Johannes Lundberg
No lag version
-- snip --
kernel`free 19
kernel`copyout 20
kernel`copyin 20
linuxkpi.ko`idr_find 21
kernel`selfdfree 24
kernel`tsc_get_timecount_low_lfence 25
kernel`__mtx_lock_flags 28
kernel`uma_zalloc_arg 30
kernel`bzero 31
i915kms.ko`gen8_ppgtt_insert_entries 31
drm.ko`drm_ioctl 32
kernel`fget_unlocked 36
kernel`amd64_syscall 37
kernel`kern_select 49
i915kms.ko`gen8_ppgtt_insert_pte_entries 61
kernel`0xffffffff80f68fbc 78
kernel`bcopy 90
i915kms.ko`fw_domains_get 228
kernel`spinlock_exit 284
kernel`cpu_idle 4698
kernel`acpi_cpu_idle 36288
I also tried rebuilding linux-c6_sdl-1.2 using get time functions in librt
vs libc but no difference.
Will dig deeper next time I have free time to spare.

Post by blubee blubeeme

I'd say dtrace might be able to get you in the right direction very quickly.
I used SDL in the past for android apps and the code is very Linux
specific. I am sure there's some Linux related timers in there somewhere
that FreeBSD is returning nothing from and that's what's killing the
performance.
I can almost guarantee that none of the SDL designers and or programmers
use any *BSD systems.
The easiest solution would be to go look at the timer code and implement
something that FreeBSD can work with and try to get that upstream.
These are just a few of the issues that will crop up when devs try to
just use shims to hook into the Linux kernel. Do the design work up front
and implement things in a native way or enjoy the jank.
DTrace should be able to point you in the right direction relatively
quickly.
The DTraceBook: https://www.amazon.com/DTrace-Dynamic-Tracing-
Solaris-FreeBSD/dp/0132091518
Best

Hans Petter Selasky

2018-01-23 12:36:56 UTC

Permalink

Post by Johannes Lundberg
Hi all
Some quick dtracing with play causing lag, vs play not causing lag (that is
not hold down any key on a usb keyboard for too long).

Hi,

The only thing I can think about is that one or more of kb_delay1 or
kb_delay2 are zero:

sys/dev/usb/input/ukbd.c

Post by Johannes Lundberg
case KDSETREPEAT: /* set keyboard repeat rate (new
* interface) */
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);
#ifdef EVDEV_SUPPORT
if (sc->sc_evdev != NULL)
evdev_push_repeats(sc->sc_evdev, kbd);
#endif
return (0);

Can you add some prints in ukbd.c where kb_delayX are set and see if
their value are zero? Lowest supported value should be 1.

--HPS

Hans Petter Selasky

2018-01-24 12:06:06 UTC

Permalink

Hi,

Can you test and review:

https://reviews.freebsd.org/D14027

--HPS

Johannes Lundberg

2018-01-24 14:07:16 UTC

Permalink

Post by Hans Petter Selasky
Hi,
https://reviews.freebsd.org/D14027

It seems better. Not as many lock_delays and lag but there still is some
lag when holding down a key for too long.

kernel`z_feed_linear_S16LE 11
kernel`uma_zfree_arg 11
i915kms.ko`gen8_ppgtt_clear_pte_range 11
kernel`bzero 12
kernel`sopoll 13
kernel`sopoll_generic 13
kernel`atomic_add_int 13
kernel`trash_ctor 14
kernel`0xffffffff80f4b548 15
kernel`callout_reset_sbt_on 16
kernel`trash_dtor 16
kernel`spinlock_enter 16
kernel`copyout 16
ichsmb.ko`ichsmb_device_intr 16
kernel`__mtx_lock_spin_flags 17
kernel`softclock_call_cc 18
kernel`selfdfree 20
kernel`uma_dbg_alloc 20
kernel`uma_dbg_free 20
kernel`uma_zalloc_arg 21
i915kms.ko`gen8_ppgtt_insert_pte_entries 21
kernel`copyin 22
kernel`amd64_syscall 22
kernel`witness_warn 23
* kernel`ukbd_interrupt 24*
kernel`fget_unlocked 24
kernel`ukbd_timeout 25
kernel`__mtx_assert 28
kernel`usbd_in_polling_mode 30
kernel`_isitmyx 33
kernel`witness_lock 47
kernel`kern_select 54
kernel`bcopy 78
kernel`__mtx_unlock_flags 79
kernel`witness_checkorder 91
kernel`memcpy 100
kernel`__mtx_lock_flags 136
kernel`witness_unlock 160
i915kms.ko`fw_domains_get 184
kernel`spinlock_exit 1904
kernel`cpu_idle 3564
* kernel`lock_delay 3634*
kernel`acpi_cpu_idle 29591

--HPS