See #143

@h1z1 I think that is a separate issue. I tried making .local/share/Steam/steamapps/common/SteamVR/bin/linux64/chmod_trace_marker into a setuid program to see if it makes a difference and it just isn't being executed. The flame graph showing __GI___kill taking most of our CPU time also implies that this issue has nothing to do with chmod_trace_marker.

I did some more profiling. These are the syscalls being executed by TheLab.exe over a 10 second interval:

SYSCALL                   COUNT
kill                   10961289
readv                    165884
poll                     126740
write                     52679
getpid                    25323
clock_gettime              5377
futex                      4482
sched_yield                3319
select                     3058
openat                     1932

It is doing ~1.1 million kill syscalls per second, which is absurd. Some more profiling shows that these are all sigzero and are being sent a few processes:

vserver ~ # /usr/share/bcc/tools/argdist -p 13482 -C 'p:c:kill(int pid, int sig):int:pid'     
[15:16:39]
p:c:kill(int pid, int sig):int:pid
        COUNT      EVENT
        13528      pid = 10803
        22349      pid = 13930
        24663      pid = 32159
        37024      pid = 7686
        103899     pid = 13482
        259419     pid = 7886
[15:16:40]
p:c:kill(int pid, int sig):int:pid
        COUNT      EVENT
        12844      pid = 10803
        21373      pid = 13930
        23570      pid = 32159
        35152      pid = 7686
        98926      pid = 13482
        247366     pid = 7886
[15:16:41]
p:c:kill(int pid, int sig):int:pid
        COUNT      EVENT
        13148      pid = 10803
        21798      pid = 13930
        24047      pid = 32159
        35984      pid = 7686
        101143     pid = 13482
        253200     pid = 7886
^Cvserver ~ # /usr/share/bcc/tools/argdist -p 13482 -C 'p:c:kill(int pid, int sig):int:sig'
[15:16:50]
p:c:kill(int pid, int sig):int:sig
        COUNT      EVENT
        440520     sig = 0
[15:16:51]
p:c:kill(int pid, int sig):int:sig
        COUNT      EVENT
        455396     sig = 0
[15:16:52]
p:c:kill(int pid, int sig):int:sig
        COUNT      EVENT
        448923     sig = 0

The profiling data showing what processes are being signaled does not show a million signals per second, but this is such a tight loop that the act of collecting the syscall arguments is likely incurring significant overhead. Here are what each of the processes in question are:

richard   7686  7661  5 15:00 pts/12   00:00:54 /home/richard/.local/share/Steam/steamapps/common/SteamVR/bin/linux64/vrserver -waitformonitor -ipccontrolfilepath /tmp/SteamVR-IPCControlFile-7663
richard   7886  7661 44 15:00 pts/12   00:07:49 /home/richard/.local/share/Steam/steamapps/common/SteamVR/bin/linux64/vrcompositor
richard  10803  7661 83 15:01 pts/12   00:14:35 /home/richard/.local/share/Steam/steamapps/common/SteamVR/bin/linux64/vrmonitor -nokillprocess
richard  13482 13288 99 15:02 pts/12   00:17:05 Z:\home\richard\.local\share\Steam\steamapps\common\The Lab\TheLab\win64\TheLab.exe -popupwindow
richard  13930 13482  5 15:02 pts/12   00:00:56 /home/richard/.local/share/Steam/steamapps/common/SteamVR//bin/linux64/vrdashboard
richard  32159 32086 16 15:00 pts/12   00:03:04 /home/richard/.local/share/Steam/ubuntu12_32/steam

It is surprising that TheLab.exe is doing signal 0 on itself. It sends the second largest number of signals to itself.

In any case, the result of the signal operation really should be cached. You can have an asynchronous worker thread update it once per second. Some code to handle the possibility of it being wrong would be needed, but kernel preemption means that you would need that code anyway because you have a TOCTOU race either way. In specific, the other process could be killed before you do whatever you are relying on signal 0 to say is safe to do.

Just a FYI, the call to kill is being done in IPC::CreateMutex. It goes through the Global Offset Table. When control moves to the kill function in glibc, it immediately executes these two instructions to do the syscall:

   362c0:       b8 3e 00 00 00          mov    $0x3e,%eax
   362c5:       0f 05                   syscall

The consequence is that the stack unwinder does not recognize the frame for IPC::CreateMutex as being different from the frame for the kill call. At least, that is my current conjecture. I have noticed the stack frame doing a syscall through glibc absent from stack traces when syscalls were recorded during perf profiling in the past, but until now, I have never looked into the possible cause.

Edit: I disassembled the wrong version of glibc for an example (32-bit rather than 64-bit), but my point about it entering the syscall immediately is applicable to both cases.

If Valve cannot fix this any time soon, would Valve please open source vrclient.so so that I could fix it for them?

Alternatively, I would be happy to settle for a “If you are such a big fan of our software that you would go through the hassle of reverse engineering and modifying binary code to fix this and post a binary patch before we fix it ourselves, we will not sue you.”.

Might interest you to run gpuvis (f6), it's a awsome little utility that gets fed data from steam via the kernel perf events. It's not always aparent what the cause is. The read calls themselves are quick. In my case it also identified an unrelated bug in the kernel wrt the clocksource.

That does not work with the Nvidia driver and I am already using perf events manually. It might be useful for non-VR things on my systems that use Intel graphics though. Thanks.

gpuvis is a frontend to visualize any perf events, with specialized visualizers for CPU and GPU scheduling events, and print events. You're right that there's no NVIDIA GPU scheduling events to visualize at the moment, but it's still valuable on the CPU/print side even on NVIDIA machines.

This issue should be fixed in SteamVR 1.7.2

I can confirm that it is fixed. :)