protonscr

High CPU when debugfs is unavailable

steamvrclosed
ValveSoftware/SteamVR-for-Linux#143 · opened 2018-10-11 by h1z1 · updated 2018-10-18 · 6 comments · github
Hh1z1 2018-10-11 github

How To Collect SteamVR System Information:

Your system information

  • Steam client version (build number or date): Oct 9 2018
  • Distribution (e.g. Ubuntu): CentOS
  • Graphics driver version (run nvidia-settings): Driver Version: 396.24
  • Gist for SteamVR System Information:
  • Opted into Steam client beta?: Yes
  • Opted into SteamVR beta?: Yes
  • Have you checked for system updates?: Yes

Please describe your issue in as much detail as possible:

vrcompositor spins consuming CPU when system tracing is unavailable due to debugfs not being mounted. It shouldn't do that. We wont' talk about the fact that this also brings X to it's knees despite the GPU having very little load (25%) nor that simply mounting debugfs drops what little load there is to ~3%. Steam still has no access to debug tracing (what distro allows that??)

Steps for reproducing this issue:

  1. Reboot.. forget to mount debugfs
  2. start steam
  3. start steamvr
  4. Pray X responds enough to kill Steam else ssh is required

strace

restart_syscall(<... resuming interrupted poll ...>) = 1
ioctl(106, _IOC(_IOC_READ|_IOC_WRITE, 0x46, 0x52, 0x10), 0x7fdab0d2bd10) = 0
clock_gettime(CLOCK_MONOTONIC, {269764, 19853170}) = 0
clock_gettime(CLOCK_MONOTONIC, {269764, 19915120}) = 0
open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY) = -1 ENOENT (No such fi
le or directory)
open("/sys/kernel/tracing/trace_marker", O_WRONLY) = -1 ENOENT (No such file or
directory)
futex(0x2631540, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
ioctl(77, _IOC(_IOC_READ|_IOC_WRITE, 0x46, 0x2a, 0x20), 0x7fdab0d2bd30) = 0
futex(0x2631540, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_MONOTONIC, {269764, 53391388}) = 0
clock_gettime(CLOCK_MONOTONIC, {269764, 53449496}) = 0
open("/proc/driver/nvidia/params", O_RDONLY) = 323
fstat(323, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd
ab2bda000
read(323, "Mobile: 4294967295\nResmanDebugLe"..., 1024) = 564

Ater mounting:

[pid 71400] 17:21:35.633530 ioctl(323, _IOC(_IOC_READ|_IOC_WRITE, 0x46, 0xcf, 0x10) <unfinished ...>
[pid 72107] 17:21:35.633557 open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY <unfinished ...>
[pid 71386] 17:21:35.633591 recvmsg(26,  <unfinished ...>
[pid 72107] 17:21:35.633623 <... open resumed> ) = -1 EACCES (Permission denied)
[pid 71400] 17:21:35.633643 <... ioctl resumed> , 0x7fdab0d2bcc0) = 0
[pid 72107] 17:21:35.633672 open("/sys/kernel/tracing/trace_marker", O_WRONLY <unfinished ...>
[pid 71386] 17:21:35.633695 <... recvmsg resumed> 0x7ffcf233d800, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 72107] 17:21:35.633741 <... open resumed> ) = -1 ENOENT (No such file or directory)
[pid 71400] 17:21:35.633763 close(323 <unfinished ...>
[pid 71386] 17:21:35.633782 poll([{fd=26, events=POLLIN|POLLPRI}], 1, 0 <unfinished ...>
[pid 72107] 17:21:35.633817 open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY <unfinished ...>

You're not reading those timestamps wrong, it's going ballistic.

I don't actually know what is going on now as it's complaining the firmware is out of date yet shows no update available??

steam[4443]: Attempting HID Open HMD: 
steam[4443]: CHidDevice: Can't open USB device VID 00000bb4, PID 00002c87  1
steam[4443]: LHR-2E711234: Attached device ID not set.  No controller input available.
steam[4443]: Attempting HID Open HMD: 
steam[4443]: Attempting HID Open IMU: LHR-FF211234
steam[4443]: Lighthouse IMU HID opened
steam[4443]: LHR-FF211234: Firmware Version 3 @�
gY[
   D!� 1969-12-31 FPGA 0(0.0/0/0) BL 0
steam[4443]: LHR-FF211234: ERROR: firmware does not meet minimum required version (1420157645). Please update device.
steam[4443]: LHR-FF211234: Successfully fetched gyro/accelerometer range modes from the device. GyroRangeMode:3 AccelRangeMode:2

Update: I was able to recover the firmware. SteamVR is however hosed to the point it stalls the GPU but not because of CPU. It literally stops rendering frames. FPS display drops to 1.

Eventually these started popping up:

[283664.151596] nvidia-modeset: ERROR: GPU:0: Idling display engine timed out: 0x0000927c:1:0
[283666.152879] nvidia-modeset: ERROR: GPU:0: Idling display engine timed out: 0x0000927c:1:0
[283679.535448] nvidia-modeset: ERROR: GPU:0: Idling display engine timed out: 0x0000927c:1:0
[283681.536444] nvidia-modeset: ERROR: GPU:0: Idling display engine timed out: 0x0000927c:1:0
[283687.921690] nvidia-modeset: ERROR: GPU:0: Idling display engine timed out: 0x0000927c:1:0
[283689.922575] nvidia-modeset: ERROR: GPU:0: Idling display engine timed out: 0x0000927c:1:0
[283703.955164] nvidia-modeset: ERROR: GPU:0: Idling display engine timed out: 0x0000927c:1:0

Possibly related: #53 ?

Restarting Steam at all results in a console flood ( hundreds per second) of

ioctl (GFEATURE): Broken pipe
ioctl (GFEATURE): Broken pipe
ioctl (GFEATURE): Broken pipe
steam[46380]: LHR-FF7F1234: Unable to fetch gyro/accelerometer range modes from the device
ioctl (GFEATURE): Broken pipe
ioctl (GFEATURE): Broken pipe

The HMD is indeed turned off. At a rate of 30/s Steam is actually spamming the hell out of SYSLOG?? What on earth.

Oct 11 22:53:21 localhost steam[47343]: LHR-FF7F1234: Unable to fetch gyro/accelerometer range modes from the device
Oct 11 22:53:21 localhost steam[47343]: LHR-FF7F1234: Unable to fetch gyro/accelerometer range modes from the device

These are no doubt now cascading problems but bugs none the less.

Hh1z1 2018-10-12 github

Further update since Valve is unlikely to respond at elast to me.

The issue with accessing debugfs remains. Likely permitted in SteamOS but allowing users to set kernel trace events is completely the wrong thing to do. ./steamapps/common/SteamVR/bin/linux64/chmod_trace_marker
... is just silly.

The HMD firmware has corrupted itself twice since this happened requiring a reflash with
steamapps/common/SteamVR/tools/lighthouse/bin/linux64/lighthouse_watchman_update

NONE of the issues above happen outside steam. Running vrstartup directly and the hellovr demo from OpenVR for example runs fine. Funny thing is if you can figure out how to launch Valve's applications directly most of them DO work, just not through Steam.

Spamming syslog and the console also appears to pound the USB bus which added to X freezing as I had the vive plugged into a hub shared with the consoles keyboard and mouse. Which brings up the last point -- Make sure your Vive is on a dedicated USB port or you run the risk of saturating not only the USB bandwidth but as I did, power (both controllers were plugged in). The Vive nor software will warn you. An excellent tool is lsusb.py (not to be confused with lsusb).

Hh1z1 2018-10-16 github

See #123 and #146 and #53 ..and...

PPlagman 2018-10-17 github

The system freezes are caused by an NVIDIA driver bug; while we wait for a fixed driver it is recommended to disable the 'Allow Flipping' NVIDIA setting on your main desktop. All the other behaviors you documented are expected.

The built-in GPU profiling tool uses ftrace for data collection, so it is useful to interleave debug messages directly with the other tracepoints by going through this debugfs interface.

Hh1z1 2018-10-17 github

Ftrace is not available though, yet the client continues trying.

Re the NVIDIA bug, which one are you refering to?

PPlagman 2018-10-17 github

Both #123 and #53 are probably caused by the NVIDIA driver bug.

It tries opening the trace_marker for every performance debugging message it prints; not ideal, but it's a fast operation if it fails, since it doesn't actually hit the disk. If you enable "GPU profiling" and restart SteamVR, it'll give you the option to run a few commands with sudo, to make trace-record and chmod_trace_marker setuid root, so that ftrace can be used for GPU profiling. Then hitting F6 on the mirror window will cut the last few seconds worth of performance data and open gpuvis for inspection. I don't have any reason to believe trying to open the ftrace device node when GPU profiling disabled is causing any issues at this point, performance or otherwise, but we can make it try less often if you have data showing it does.

Hh1z1 2018-10-18 github
$ { date; strace -f -p  `pidof vrcompositor` -c & sleep 10; kill $! ;date; }
Thu Oct 18 10:31:52 EDT 2018
[1] 103607
strace: Process 103343 attached with 7 threads
strace: Process 103343 detached
strace: Process 103350 detached
strace: Process 103351 detached
strace: Process 103353 detached
strace: Process 103354 detached
strace: Process 103358 detached
strace: Process 103501 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 46.56    8.589664       43164       199           select
 21.11    3.894412        4215       924           nanosleep
 16.75    3.089836        1129      2737           poll
  6.07    1.119150          12     92979           clock_gettime
  4.02    0.741729          13     55298     53514 open
  2.45    0.452054          51      8841       456 futex
  1.68    0.309183          43      7136           ioctl
  0.27    0.049830          18      2769           tgkill
  0.21    0.038862          22      1784           close
  0.16    0.029523          11      2675           getpid
  0.16    0.028802          32       892           read
  0.13    0.023504          26       892           munmap
  0.12    0.022060          25       892           mmap
  0.10    0.018275          20       923       923 recvmsg
  0.08    0.015447          17       892           fstat
  0.08    0.014434          16       892           stat
  0.06    0.010758          12       892           fcntl
  0.02    0.003039        1013         3           restart_syscall
------ ----------- ----------- --------- --------- ----------------
100.00   18.450562                181620     54893 total
Thu Oct 18 10:32:02 EDT 2018
[1]+  Done                    strace -f -p `pidof vrcompositor` -c

5.5k calls/s and 18 seconds CPU for a process sitting idle. It is essentially pegging a CPU @ 4GHz

Nothing extracted yet.