The Linux evdev sound API is very slow to open(2) the device

[NoSuck]

Thank you for overseeing this project.

Cursed to use Arch Linux on one, last machine for the foreseeable future, one of the beep packages I use recently pointed its upstream URL your way (1.3-4 -> 1.4.4-1).

I set up permissions using the beep group method described in PERMISSIONS.md and immediately noticed sluggish, staggered response. Consider the following eight-note scale:

■ Test () { beep -l 250 -f 262 ; beep -l 250 -f 294 ; beep -l 250 -f 330 ; beep -l 250 -f 349 ; beep -l 250 -f 392 ; beep -l 250 -f 440 ; beep -l 250 -f 494 ; beep -l 250 -f 523 ; } ; time Test

real    0m2.466s
user    0m0.012s
sys     0m0.008s

In other words, your fork takes 23% longer to execute than it should--and it staggers from note to note. Do you know why? Do you know of any workarounds?

Thank you for reading.

■ uname -srvmo
Linux 5.0.7-arch1-1-ARCH #1 SMP PREEMPT Mon Apr 8 10:37:08 UTC 2019 x86_64 GNU/Linux

[ndim]

I would just use a single beep invocation for playing a sequence of beeps:

#!/bin/sh
Test () { beep -l 250 -f 262 -n -l 250 -f 294 -n -l 250 -f 330 -n -l 250 -f 349 -n -l 250 -f 392 -n -l 250 -f 440 -n -l 250 -f 494 -n -l 250 -f 523 ; }
time Test

real	0m2.011s
user	0m0.000s
sys	0m0.002s

As to why new beep would be slower than old beep, I will have to think about that a bit first.

[NoSuck]

Thank you for the feedback. To clarify, slowdown is introduced by beep invocations, which is why the Test function I provided is the way it is. What sort of time output does your system show for the original Test?

[ndim]

Sorry I misunderstood your actual concern.

The original Test() reports

real	0m2.088s
user	0m0.005s
sys	0m0.012s

here. That gives around 11ms per invocation, which is consistent with the

real	0m2.011s

of the one invocation Test().

My system is an about 5 to 8 year old AMD A6-3500 3 core 2GHz(-ish?) with 16GB not at all swapping, running Fedora 29.

[NoSuck]

Thank you.

I will try the other permissions setups (“all other users” with GROUP="beep" and “users currently logged into virtual console”). I am unable to do this now, as my changes to udev rules files do not seem to take effect with udevadm control --reload and udevadm trigger, and I am unable to reboot the system until later.

Just to be safe, I downgraded beep to the original for a side-by-side comparison:

#!/usr/bin/env -S bash --

beep -l 250 -f 262
beep -l 250 -f 294
beep -l 250 -f 330
beep -l 250 -f 349
beep -l 250 -f 392
beep -l 250 -f 440
beep -l 250 -f 494
beep -l 250 -f 523

■ time ./beepTest # 1.3-4

real    0m2.021s
user    0m0.011s
sys     0m0.009s

■ time ./beepTest # 1.4.4-1
real    0m2.524s
user    0m0.017s
sys     0m0.004s

I also compared strace output. It was identical in all the parts that could be reasonably expected to be identical. 😕

By the way, what were the “few serious security issues for beep in 2018” mentioned in PERMISSIONS.md? I never considered setuid a serious problem, so I am curious as to what actually happened. Were incidents reported?

[ndim]

The permission setup happens whenever the pcspkr.ko kernel module is loaded and creates the devices, which usually happens once on system bootup, or later when you manually modprobe pcspkr.

The permission setup does not happen when you run beep.

What is different between old beep and new beep?

Old beep, for each beep it does, opens /dev/tty0 (and failing that, /dev/vc/0) and calls the KIOCSOUND ioctl on it to start and stop the sound. If you give old beep a different device to use (such as e.g. /dev/input/by-path/platform-pcspkr-event-spkr), it will use that instead.

New beep opens /dev/input/by-path/platform-pcspkr-event-spkr once and writes a few bytes to it to start and stop the sound however many times requested. However, new beep checks a few more things, and has a bit more infrastructure code to initialize, which is probably where it loses a bit of time. As to where exactly new beep loses those milliseconds, I will have to investigate by profiling the program.

I do not see those few milliseconds as a huge issue in practical use, but now that you have pointed this out I do want to know how exactly this happens, how this can be examined, and also how this could be improved (and what are the tradeoffs). Not my biggest priority, though.

As to the security issues, see CVE-2018-0492 and CVE-2018-1000532. Both are covered in the johnath#11 issue.

[NoSuck]

As to the security issues, see CVE-2018-0492 and CVE-2018-1000532.

I was wondering about incidents reported, partly because I think it would be hilarious but mostly because I am curious about the CVE's relevance in the real world.

Thank you for maintaining an interest in this bug. I am sorry I was not able to help much in pinpointing the cause.

[ndim]

Being unfamiliar with either of them, I have just tried gprof and oprofile on beep and did not find any useful data.

After inserting exit(EXIT_SUCCESS); at various points within the beep sources and running time beep -f 2222 -l 1000 a number of times, my impression is that beep_drivers_detect() takes about 80% of beep's startup time.

That is 100% code which I have written after taking over the beep source in order to separate the specific beeping API from the main beep program.

The question is whether it makes sense for beep to support more than the evdev API. If not, the need for having more than one driver goes away and we will not need the beep driver infrastructure, saving about 80% of program startup.

[ndim]

The actual line which takes about 80% of startup time appears to be, as determined again via exit(EXIT_SUCCESS); and _exit(EXIT_SUCCESS);

/* const char *device_name = "/dev/input/by-path/platform-pcspkr-event-spkr"; */
const int fd = open(device_name, O_WRONLY);

Why? No idea.

Opening that device_name cannot be worked around at all, so I do not see what I could do about that.

[ndim]

I just checked these two programs which just open the device file.

Representing old beep with the console KIOCSOUND API:

#include <stdlib.h>
#include <unistd.h>

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>

int main(void)
{
  const int fd = open("/dev/tty5", O_WRONLY);
  close(fd);
  return EXIT_SUCCESS;
}

and representing new beep with the evdev API:

#include <stdlib.h>
#include <unistd.h>

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>

int main(void)
{
  const int fd = open("/dev/input/by-path/platform-pcspkr-event-spkr", O_WRONLY);
  close(fd);
  return EXIT_SUCCESS;
}

It turns out that the console API skeleton takes between 1ms and 2ms and the evdev API skeleton takes 9ms to 14ms (BTW, directly opening the target of the symlink does not change the evdev times, FWIW).

So I would blame the additional 8ms to 12ms on the kernel, and, from a beep point of view, close this bug without a fix. If you are using beep for a sequence of beeps, use -n instead of invoking beep multiple times, and the timing issue should disappear.

[ndim]

If I change these skeleton test programs to run the open() and close() in a loop for 1000 times, it turns out that opening /dev/tty5 1000 times takes about 8ms, while opening /dev/input/by-path/platform-pcspkr-event-spkr 1000 times takes between 14.8s and 17.5s, i.e. about 2000 times as long.

No idea why.

[NoSuck]

You are very diligent. I tried the looped test and saw even worse results than you did (with su):

■ time ./testKernelEvdev # /dev/tty5

real    0m0.011s
user    0m0.000s
sys     0m0.011s
■ time ./testKernelEvdev # /dev/input/by-path/platform-pcspkr-event-spkr

real    0m59.463s
user    0m0.027s
sys     0m0.024s

#include <stdlib.h>
#include <unistd.h>

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>

void open_and_close(void)
{
	//const int fd = open("/dev/input/by-path/platform-pcspkr-event-spkr", O_WRONLY);
	const int fd = open("/dev/tty5", O_WRONLY);
	close(fd);
}

int main(void)
{
	for(unsigned int u = 0 ; u < 1000 ; u++)
	{
		open_and_close();
	}
	return EXIT_SUCCESS;
}

How frustrating.

[ndim]

Running issue-6-benchmark on my system from a virtual console gives the following results, which I am going to interpret below.

/usr/bin/time -v ./issue-6-benchmark 5407515 /dev/tty4
device_name    = /dev/tty4
counters[succ] = 5407515
counters[fail] = 0
Command being timed: "./issue-6-benchmark 5407515 /dev/tty4"
User time (seconds): 0.58
System time (seconds): 14.89
Percent of CPU this job got: 93%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:16.51
Average shared text size (kbytes): 0
Average unshared data size (kbytes): 0
Average stack size (kbytes): 0
Average total size (kbytes): 0
Maximum resident set size (kbytes): 1760
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 0
Minor (reclaiming a frame) page faults: 79
Voluntary context switches: 0
Involuntary context switches: 10087
Swaps: 0
File system inputs: 0
File system outputs: 0
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0

/usr/bin/time -v ./issue-6-benchmark 1237 /dev/input/by-path/platform-pcspkr-event-spkr
device_name    = /dev/input/by-path/platform-pcspkr-event-spkr
counters[succ] = 1237
counters[fail] = 0
Command being timed: "./issue-6-benchmark 1237 /dev/input/by-path/platform-pcspkr-event-spkr"
User time (seconds): 0.00
System time (seconds): 0.09
Percent of CPU this job got: 0%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:16.63
Average shared text size (kbytes): 0
Average unshared data size (kbytes): 0
Average stack size (kbytes): 0
Average total size (kbytes): 0
Maximum resident set size (kbytes): 1852
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 0
Minor (reclaiming a frame) page faults: 80
Voluntary context switches: 2475
Involuntary context switches: 7
Swaps: 0
File system inputs: 0
File system outputs: 8
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0

The first obvious thing is that 5407515 times opening the console device /dev/tty4 takes 16.51 seconds, and 1237 times opening the evdev device /dev/input/by-path/platform-pcspkr-event-spkr takes 16.63 seconds. So opening the evdev device takes about 13.4ms, and opening the console device takes about 3.1us, which makes opening the evdev device about 4400 times as slow.

Now, let us read the output of /usr/bin/time -v to see what the differences are.

For the console device, opening 5407515 times takes 0.58 seconds of user time, 14.89 seconds of system time, which about adds up to 16.51 seconds of wall clock time. Also, the console device causes 0 voluntary context switches and 10087 involuntary context switches. So far, so good.

For the evdev device on the other hand, opening 1237 times takes 0.00 seconds of user time, 0.09 seconds of system time, which is just about nothing compared to the 16.63 seconds of wall clock time. So for more than 99% of the elapsed wall clock time, the computer appears to be doing things that are neither user time nor system time.

Also, the evdev device causes 2475 voluntary context switches and 7 involuntary context switches. This is remarkably different from the case of the console device: Every open(2)-and-close(2) cycle appears to cause almost exactly two voluntary context switches.

Are just 2475 voluntary context switches taking all that 16.54 seconds of neither-system-nor-user time?

Also, why is the time taken by context switches not be counted as system time?

The time taken for the 7 involuntary context switches appears negligible, as the console device test case manages 10087 of those without causing taking too much time that is neither user time nor system time.

At this time, I have not yet dug further down into the Linux kernel (glibc is probably not to fault, unless it exhibits different behaviour depending on the filename string passed to open(2)) to find out where those context switches might be caused, why opening those different devices does context switches so wildly differently, and whether this could be changed to improve open(2) times for beep without compromising other aspects of the device behaviour.