search

polygraphene / ALVR

ALVR is an open source remote VR display for Gear VR and Oculus Go. With it, you can play SteamVR games in your standalone headset.
MIT License
1.82k stars 248 forks source link

Low framerate #116

Closed saintkamus closed 2 years ago

saintkamus commented 6 years ago

FPS in game are locked to 72 (matching the refreshrate of the Go) But the actual framerate in the headset is much lower.

Don't know if it's an issue with the decoding side of things, or the encoding, but the game looks silky smooth on the PC (again, locked at 72 FPS) but looks choppy in the headset.

This issue is not to be confused with the headtracking, which works flawlessly because of ATW. The headtracking looks just as smooth as any other Go app. The problem is with the actual framerate of the game.

I've tried multiple versions (currently using the latest one as of 7/22/2018) and they all have this issue.

I'm using a 5ghz router that is very nearby, computer connected with Ethernet, and the issue is present using any bitrate or resolution. (4k runs at exactly the same FPS as 1024x512. I'm using a 1080ti with an overlocked 4.5ghz Core i5.)

TL;DR: there seems to be an issue with either the encoding or decoding of the video that results in low FPS on the headset.

vrokolos commented 6 years ago

Maybe you're seeing this thing here: https://github.com/polygraphene/ALVR/issues/42#issuecomment-399364452

(read the whole thread)

-- duplicate: https://github.com/polygraphene/ALVR/issues/60

polygraphene commented 6 years ago

You can check real FPS on headset by adb like the followings. not ready. discard. means the frame drop because the frame arrives too early. I'm working on this issue, so please be patient.

> adb shell
$ logcat | grep -E "(discard|FPS)"
07-03 15:53:26.689 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:27.627 31748 31997 I VrApi   : FPS=54,Prd=76ms,Tear=0,Early=4,Stale=34,VSnc=1,Lat=0,Fov=0,CPU4/GPU=3/3,1190/342MHz,OC=FF,TA=F0/F0/0,SP=N/N/N,Mem=1554MHz,Free=731MB,PSM=0,PLS=0,Temp=39.2C/30.0C,TW=0.00ms,App=0.00ms
07-03 15:53:27.725 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:28.547 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:28.636 31748 31997 I VrApi   : FPS=55,Prd=76ms,Tear=0,Early=1,Stale=33,VSnc=1,Lat=0,Fov=0,CPU4/GPU=3/3,1190/342MHz,OC=FF,TA=F0/F0/0,SP=N/N/N,Mem=1554MHz,Free=728MB,PSM=0,PLS=0,Temp=39.2C/30.0C,TW=0.00ms,App=0.00ms
07-03 15:53:28.732 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:29.181 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:29.623 31748 31997 I VrApi   : FPS=51,Prd=79ms,Tear=1,Early=0,Stale=38,VSnc=1,Lat=0,Fov=0,CPU4/GPU=3/3,1190/342MHz,OC=FF,TA=F0/F0/0,SP=N/N/N,Mem=1554MHz,Free=728MB,PSM=0,PLS=0,Temp=39.2C/30.0C,TW=0.00ms,App=0.00ms
07-03 15:53:29.733 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:29.883 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:30.185 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:30.435 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:30.537 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:30.639 31748 31748 V DecoderThread: not ready. discard.
07-03 15:53:30.646 31748 31997 I VrApi   : FPS=59,Prd=74ms,Tear=0,Early=0,Stale=28,VSnc=1,Lat=0,Fov=0,CPU4/GPU=3/3,1190/342MHz,OC=FF,TA=F0/F0/0,SP=N/N/N,Mem=1295MHz,Free=727MB,PSM=0,PLS=0,Temp=39.2C/30.0C,TW=0.00ms,App=0.00ms
saintkamus commented 6 years ago

Thanks for your hard work! I'm glad to learn that you're aware of the issue and working to solve it!

vrokolos commented 6 years ago

I've been testing 2.2.3 with that "never drop frames option".

The microstutter hasn't vanished but it changed. I think it got better. I know for sure that for 5 seconds I managed to have buttery smooth framerate with no frame loss whatsoever. Those "5 seconds periods" weren't there without that option. But those 5 seconds smooth moments are scarce and I need more of those.

I will try different settings / lower quality to raise FPS etc and see how it goes from there. The sound gets messy with that option on however.

polygraphene commented 6 years ago

@vrokolos We need to tune some parameters. Can you show me the logcat output?

vrokolos commented 6 years ago

https://github.com/polygraphene/ALVR/issues/109#issuecomment-403586836 https://github.com/polygraphene/ALVR/issues/109#issuecomment-403592231

Those two. Similar jerkiness.

I didn't find anything on the log about dropped frames however.

Also even having everything on lowest detail still didn't prevent stuttering so it's a client/transport/server VSYNC issue I guess

polygraphene commented 6 years ago

Thank you!

07-09 22:18:23.296 13568 13590 V FrameTracking: [Frame 37076] totalLatency=89755 transportLatency=2611 decodeLatency=5677 07-09 22:18:23.306 13568 13839 V FrameTracking: [Frame 37082] Sending tracking info. 07-09 22:18:23.323 13568 13839 V FrameTracking: [Frame 37083] Sending tracking info. 07-09 22:18:23.340 13568 13839 V FrameTracking: [Frame 37084] Sending tracking info. 07-09 22:18:23.357 13568 13839 V FrameTracking: [Frame 37085] Sending tracking info. 07-09 22:18:23.373 13568 13839 V FrameTracking: [Frame 37086] Sending tracking info. 07-09 22:18:23.390 13568 13839 V FrameTracking: [Frame 37087] Sending tracking info. 07-09 22:18:23.406 13568 13839 V FrameTracking: [Frame 37088] Sending tracking info. 07-09 22:18:23.413 13568 13590 V FrameTracking: [Frame 37077] Frame latency is 190117 us. foundFrameIndex=37077 LatestFrameIndex=37088 07-09 22:18:23.415 13568 13590 V FrameTracking: [Frame 37077] totalLatency=190677 transportLatency=146240 decodeLatency=9486 07-09 22:18:23.418 13568 13590 V FrameTracking: [Frame 37078] Frame latency is 178302 us. foundFrameIndex=37078 LatestFrameIndex=37088 07-09 22:18:23.423 13568 13839 V FrameTracking: [Frame 37089] Sending tracking info. 07-09 22:18:23.434 13568 13590 V FrameTracking: [Frame 37078] totalLatency=194028 transportLatency=117266 decodeLatency=9261 07-09 22:18:23.437 13568 13590 V FrameTracking: [Frame 37082] Frame latency is 131016 us. foundFrameIndex=37082 LatestFrameIndex=37089 07-09 22:18:23.440 13568 13839 V FrameTracking: [Frame 37090] Sending tracking info. 07-09 22:18:23.446 13568 13590 V FrameTracking: [Frame 37082] totalLatency=139965 transportLatency=2953 decodeLatency=14526 07-09 22:18:23.454 13568 13590 V FrameTracking: [Frame 37087] Frame latency is 64700 us. foundFrameIndex=37087 LatestFrameIndex=37090 07-09 22:18:23.456 13568 13839 V FrameTracking: [Frame 37091] Sending tracking info. 07-09 22:18:23.473 13568 13839 V FrameTracking: [Frame 37092] Sending tracking info. 07-09 22:18:23.475 13568 13897 I VrApi : FPS=22,Prd=42ms,Tear=0,Early=19,Stale=47,VSnc=1,Lat=0,Fov=0,CPU4/GPU=3/3,650/0MHz,OC=FF,TA=F0/F0/0,SP=N/N/N,Mem=0MHz,Free=973MB,PSM=0,PLS=0,Temp=41.0C/36.5C,TW=0.00ms,App=0.00ms

This is a part of your second log. From 22:18:23.296 to 22:18:23.413 (about 120ms) client didn't receive any frames. In addition, the log shows no packet loss. This is because server can't send frames for some reason (such as high CPU/GPU usage).

Can you show me the driver.log? Instruction is here. Sorry for taking up your time again.

vrokolos commented 6 years ago

I'll do that later but this isn't the statter I'm talking about. I'm talking about 1 missed frame at a time. Not 10. Or so I think

vrokolos commented 6 years ago

adb logcat: https://1drv.ms/u/s!AghkviLYNl5k0ewqMbLgEnWcTCsDjg driver.log: https://1drv.ms/u/s!AghkviLYNl5k0ewp4k_dmcbucRh5aw

I did one more test. This might be related to my CPU/GPU as you said. During skyrim VR while inside a house it was smooth. When I went outside it started stuttering. So this might be a false flag.

EDIT: my log is full of this error: sendto error: 10035 A non-blocking socket operation could not be completed immediately.

Might be related?

polygraphene commented 6 years ago

[17:18:25.425 188] Encoding delay: 11509 us FrameIndex=8214 [17:18:25.441 699] Encoding delay: 11508 us FrameIndex=8215 [17:18:25.458 711] Encoding delay: 11508 us FrameIndex=8216 [17:18:25.475 223] Encoding delay: 11007 us FrameIndex=8217 [17:18:25.492 235] Encoding delay: 12008 us FrameIndex=8218 [17:18:25.804 458] Encoding delay: 307219 us FrameIndex=8219 [17:18:25.818 469] Encoding delay: 13010 us FrameIndex=8237 [17:18:26.064 143] Encoding delay: 245174 us FrameIndex=8238 [17:18:26.085 658] Encoding delay: 13509 us FrameIndex=8246 [17:18:26.330 833] Encoding delay: 236669 us FrameIndex=8254 [17:18:26.343 342] Encoding delay: 12009 us FrameIndex=8261 [17:18:26.596 522] Encoding delay: 15511 us FrameIndex=8277 [17:18:26.610 031] Encoding delay: 14510 us FrameIndex=8282

There are some irregular encoding delays. The delays show 11.5ms normally, but sometimes show 200~300ms. This lead to lower FPS. This may be a NVENC issue.

I'll do that later but this isn't the statter I'm talking about. I'm talking about 1 missed frame at a time. Not 10. Or so I think

I didn't see other cause of low frame rate from the log. The stopping durations seem to vary (70ms~300ms) every time.

EDIT: my log is full of this error: sendto error: 10035 A non-blocking socket operation could not be completed immediately.

Probably not related. This is caused by my dirty code and (may) not harmful.

polygraphene commented 6 years ago

Please try to lower graphic setting for game (disable anti-alias or lower resolution). And check GPU temperature, usage or some other metrics.

penkamaster commented 6 years ago

@vrokolos @saintkamus try this version. https://drive.google.com/file/d/1c8Z-gUF78bBNhIoqf3QCjtbHGhabNU-1/view?usp=sharing

it forces 60 fps on the go. in my case it has removed all the microstuttering.

good luck.