Vive controllers power off after consecutive SendOnPoseChange events

[harperhendee]

Seems like many users have encountered an error where one of the controllers is lost and powers down.  I have some interesting data on the issue.  First off, I'm playing with virtual machines.  When I hook my Vive into my steambox, no loss of controller.  When I hook the Vive into a VM via my PCIE USB card, I get a high rate of drops.  When I route it through one of my on-board USB controllers, I get a lower rate of drops.  Here's a typical drop in vrserver.txt

Mon Mar 20 2017 21:52:32.161 - Sending InputFocusCaptured old=0 new=8884
Mon Mar 20 2017 21:52:34.478 - Releasing input focus for vrcompositor (8884) because of message. new focus is 0.
Mon Mar 20 2017 21:52:34.478 - Sending VREvent_InputFocusReleased old=8884 new=0
Mon Mar 20 2017 21:52:35.527 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 0.563200ms
Mon Mar 20 2017 21:53:19.862 - lighthouse: LHR-F766BF45 C: SendOnPoseChange took 0.854019ms
Mon Mar 20 2017 21:56:25.013 - lighthouse: LHR-0D3CA9A9 H: SendOnPoseChange took 0.506210ms
Mon Mar 20 2017 21:56:25.303 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 0.519898ms
Mon Mar 20 2017 21:56:25.482 - lighthouse: LHR-F766BF45 C: SendOnPoseChange took 0.607340ms
Mon Mar 20 2017 21:56:29.278 - lighthouse: LHR-F766BF45 C: SendOnPoseChange took 0.571581ms
Mon Mar 20 2017 21:56:30.609 - lighthouse: LHR-0D3CA9A9 H: SendOnPoseChange took 0.697575ms
Mon Mar 20 2017 21:56:30.707 - 4 - entering standby
Mon Mar 20 2017 21:56:30.707 - lighthouse: Device LHR-FFA49F41 powering off upon entering standby.
Mon Mar 20 2017 21:56:30.708 - 4 - leaving standby
Mon Mar 20 2017 21:56:31.395 - lighthouse: 8B14732891: Wireless controller disconnected
Mon Mar 20 2017 21:56:31.395 - lighthouse: LHR-FFA49F41: Disconnected from receiver 8B14732891
Mon Mar 20 2017 21:56:31.395 - lighthouse: LHR-FFA49F41 C: Dropped 2566 back-facing hits during the previous tracking session
Mon Mar 20 2017 21:56:33.968 - Capturing input focus for vrcompositor (8884). Old focus was 0. Focus stack size 0
Mon Mar 20 2017 21:56:33.968 - Sending InputFocusCaptured old=0 new=8884
Mon Mar 20 2017 21:57:00.038 - lighthouse: LHR-FFA49F41: Connected to receiver 8B14732891
Mon Mar 20 2017 21:57:00.192 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 1.974553ms
Mon Mar 20 2017 21:57:00.524 - lighthouse: LHR-FFA49F41 C: basestation transmission profile (ootx) selected, max basestations: 2
Mon Mar 20 2017 21:57:00.647 - lighthouse: LHR-FFA49F41 C: tdm sync acquired

 

From what I can tell, the key ingredient is latency.  When I run it on a VM, the latency is greater to service the SendOnPoseChange, and I get more controller drops.  It looks like 2 consecutive SendOnPoseChanges that take longer than .5ms within a second will do it.  

 

Is it possible to tune the timeout value that SendOnPoseChanges is sensitive to?  I think a value of 2ms would mean I never lost the controller.  

 

[harperhendee]

Here is a link to all my log files:

https://drive.google.com/file/d/0B7ky_0GX-JUBUjBnTTAzUDBJUjg/view?usp=sharing

 

[Synthesis]

That's a pretty cool set up you're working on! Currently, SteamVR is designed to run locally and isn't optimized for use through a VM. However, you might be interested to know that at VMWorld 2016, Nvidia showed off their GRID technology in partnership with VMware, so large scale VR on VM is something that's on the horizon. 

 

Thanks!

-John C

[harperhendee]

I have read other users who had similar problems with controllers powering off unexpectedly.  I think the root cause is this timeout.  The "disable power management" button seems like it is focused directly on this issue.  But it is really hard to see if it is doing anything at all.  It is a single-event button instead of a radio button.  Clicking the button doesn't appear to change any configuration file.  

Where can I find more technical data?  Do I need to join a developer program?  I'm looking for low level information so that I can make my system work.  Right now the oculus system works just fine via PCI passthru, but the Vive is constantly dropping the controller.   

Here's a outline of the system:

[Synthesis]

That's quite the rig you've got there! Let me look into this tomorrow and see if there is some sort of developer group that would be able to better help you with this.

 

Thanks,
-John C

[Jad]

There was a SteamVR beta update today (1490145859) that provided further fixes for controllers turning off while in use. Opt into the beta and give it a try. 

[Synthesis]

Great! Let us know!

[harperhendee]

This beta patch totally fixed the problem.  I played through an entire Audioshield session with no loss of controllers.  The logs show a number of extra long SendOnPoseChange events, but never drops the controller.  I'm not sure if I ever felt the effect of loss of tracking during these multi-milisecond hangs.  There were a couple of times I thought I should have been catching a ball but didn't get haptic feedback.  Not sure if there was a tracking error with the controller or the Controller (me).  

 

A new problem cropped up on this patch though.  Gunjack has always complained about unsupported controllers, but then given me perfectly usable controls in game (even if the controllers aren't rendered).  When I switched to the beta, Gunjack stopped recognizing any input from the controllers, even though I was able to interact with the dashboard just fine.

 

Here's a snippet of the log showing the unusually long SendOnPoseChange eventts:

Wed Mar 22 2017 05:30:59.627 - Unsetting system.generated.audioshield.exe PID because SetApplicationPid came in with a different key
Wed Mar 22 2017 05:30:59.627 - Setting app steam.app.412740 PID to 13280
Wed Mar 22 2017 05:30:59.627 - Using existing HMD lighthouse.LHR-0D3CA9A9
Wed Mar 22 2017 05:31:05.454 - lighthouse: LHR-F766BF45 C: SendOnPoseChange took 0.895086ms
Wed Mar 22 2017 05:31:05.456 - lighthouse: LHR-0D3CA9A9 H: SendOnPoseChange took 0.685562ms
Wed Mar 22 2017 05:31:33.765 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 6.296331ms
Wed Mar 22 2017 05:31:33.765 - lighthouse: LHR-F766BF45 C: SendOnPoseChange took 3.442058ms
Wed Mar 22 2017 05:31:33.765 - lighthouse: LHR-0D3CA9A9 H: SendOnPoseChange took 5.808559ms
Wed Mar 22 2017 05:31:51.468 - AppTransition: Aborting external launch because of timeout after 0.0019989 seconds
Wed Mar 22 2017 05:31:51.468 - Aborting launch of 'steam.app.412740'
Wed Mar 22 2017 05:31:51.499 - Capturing input focus for vrcompositor (5908). Old focus was 0. Focus stack size 0
Wed Mar 22 2017 05:31:51.499 - Sending InputFocusCaptured old=0 new=5908
Wed Mar 22 2017 05:31:53.625 - Releasing input focus for vrcompositor (5908) because of message. new focus is 0.
Wed Mar 22 2017 05:31:53.625 - Sending VREvent_InputFocusReleased old=5908 new=0
Wed Mar 22 2017 05:31:56.335 - lighthouse: LHR-F766BF45 C: SendOnPoseChange took 0.529956ms
Wed Mar 22 2017 05:31:56.335 - lighthouse: LHR-0D3CA9A9 H: SendOnPoseChange took 0.540292ms
Wed Mar 22 2017 05:32:04.861 - lighthouse: LHR-0D3CA9A9 H: SendOnPoseChange took 0.570464ms
Wed Mar 22 2017 05:32:04.861 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 0.521295ms
Wed Mar 22 2017 05:32:16.568 - lighthouse: LHR-F766BF45 C: SendOnPoseChange took 0.566832ms
Wed Mar 22 2017 05:32:16.568 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 0.567111ms
Wed Mar 22 2017 05:32:16.568 - lighthouse: LHR-0D3CA9A9 H: SendOnPoseChange took 0.598121ms
Wed Mar 22 2017 05:32:41.989 - lighthouse: LHR-0D3CA9A9 H: SendOnPoseChange took 0.502857ms
Wed Mar 22 2017 05:32:41.989 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 0.522971ms
Wed Mar 22 2017 05:33:17.599 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 0.533308ms
Wed Mar 22 2017 05:33:44.476 - lighthouse: LHR-FFA49F41 C: SendOnPoseChange took 0.529397ms

 

I notice that the longest delays are associated with all three endpoints.   This would indicate an upstream problem with either USB signal integrity, PCI bridging, KVM hosting, or the XHCI driver.