Rumble/LED state changes lost if sent too fast to the controller

[Kanuan]

The issue

2 or more Output Reports sent too fast to the controller will cause only the first to be correctly interpreted and only after commands stop being received by the controller for some time.

Summary

LEDs and Rumble state changes are sent in Output Report (OutRep) to the controller that always contains both informations and represent the current status of the controllers LEDs and Motors. If 2 or more OutRep are sent too close to each other only the first will be correctly interpreted by the controller and its content will only be in effect when the controller stops receiving new OutRep. Some models of ps3 controllers (e.g.: sixaxis CECHZC1U, DualShock 3 CECHZC2U rev1) are more prone to this issue, though chances are it can happen with any controller when commands are sent too fast (reproduced with a DualShock 3 CECHZC2U rev2).

Examples (tested with Sixaxis controller, model CECHZC1U)

• Turn Rumble ON -> wait 15ms -> Turn Rumble OFF // Result: Rumble OFF OutRep is lost, Rumble stays on
• Set LED 1 -> wait 15ms -> Set LED 2 // Result: LED 1 will stay set
• Set LED 1 -> wait 500ms -> Set LED 2 -> wait 15ms -> Set LED 3 100 times with 15ms waiting time between repeats // Result: Led 1 will be set, Led 2 will be set only after the controller stops receiving the "set LED 3" OutRep.

Problems caused by this

The bigger issue is a "Turn Rumble OFF" command being lost, making the controller vibrate for a time longer than what the aplication/game intended (as reported by #16 ) or for it to continue vibrating indefinitely until a new valid "Turn Rumble OFF" command is received.

Reproducing the problem

This issue can be easily reproduced by using this Auto DsHIDMini Test Tool along with the latest DsHidMini driver.
The controller needs to be the only ps3 controller connected to the computer, be in "SXS" mode and the Deduplication and Output Rate Control functions need to be both disabled.

By choosing to run the Auto DsHidMini Test Tool on the "auto" setting, it will:

• Set LED 1 / Turn Rumble ON -> wait "X"ms -> Set LED 2 / Turn Rumble OFF, then repeat this 20 times
• After it finished repeating 20 times, it will make the waiting time shorter, then reset and start sending the commands sequence 20 times again. The "X" waiting time starts at 110ms and decreases by 10 every cycle of test, until it tests with 1ms and then with no waiting time.

The expected behavior is for the controller to vibrate for only a instant before stopping and setting LED2 as ON. As the waiting time between the commands start getting shorter, the controller will start failing to correctly execute the Output Report, not setting LED 2 as ON and continuing to vibrate for ~500ms. Controller more prone to the issue (like the Sixaxis) will start failing at around a 90ms waiting time, while good controllers will only fail below the 20ms range.

Keep in mind that because the Auto DsHidMini Test Tool has to depend on the windows scheduler, waiting times in the test that are shorter than 16ms will start to get inaccurate (e.g.: a waiting time of 10ms will probably result in a 15 or higher waiting time in real time)

Testing

Because the Sixaxis can't rumble, the Output Report being received could only be verified by checking the LED state.
With the test tool, waiting times shorter than 100ms resulted in the sixaxis failing to process the incoming Output Report sometimes, with the frequency increasing as the waiting time got shorter.
Since the waiting time in the tool is not real-time accurate, wireshark was used to see the actual time-stamp of the OutReps being sent. It was verified that a packet was lost after being sent ~95ms after another one.

Testing with a Dualshock 3 Model CECHZC2M only resulted in a fail when Output Reports were sent with a time difference of 25ms, though the acceptable time difference between packets is not constant, as some times it would ignore Packets sent to it that were sent slower than other ones.

Problems with the current solution

The deduplication function will discharge Output Requests that are 100% equal to the last successfully sent one, so a game spamming "rumble on" will cause only the first request to be sent to the controller and the rest discharged until a different command is sent ("rumble off", "rumble in another intensity").
The Output Rate control function discharges every new command received if they arrive too close to the last one sent. This ensures the first command received is actually processed by the controller, since as stated in the Examples section, when multiple commands are sent too fast to the controller all commands after the first are ignored and the first sent one will only be effective when the controller stops receiving new ones.

While these functions mitigate the issue, they are prone to the following problems:

• If a game is sending multiple times, during the span of some seconds, the command "Rumble for 1s" in order to refresh its duration, deduplication will ignore new commands after the first, making the controller stop rumbling before the expected time
• Output Rate control can cause important commands to be discharged. If a "Rumble OFF" command is sent too close to a "Rumble ON forever" the former will be discharged, making the controller keep vibrating and forcing the user to turn off the controller or cause a new rumble event in the hope that another "Rumble OFF" is sent

Proposed solution

• Implement a Async Countdown timer that starts counting from the moment a Output Report is sent
• If the Countdown Timer is active, save new received commands in a cache
• The cache should hold only 1 command, with new received commands overwriting the previous saved one, ensuring only the latest received command is saved
• After the Timer finishes counting the cached command is sent, the cache cleared and the Countdown Timer restarted
• If there are no command on cache when the Countdown Timer finishes then the Timer is disabled, ensuring a new received command is immediately sent with no delay

The image below illustrate the proposed solution:

Because the cache only holds the latest received command on the period the Countdown Timer is active there is no risk of a "To send" commands list getting longer and resulting in a delay in Rumble/LED changes events. Though there are still lost commands, only the latest received one is of actual importance, since it contains the most recent state the controller should be in.

To-do

• Verify output report loss on cable

[Hubert365]

Just to have it on record:

I failed once at 130ms, failed 3 times at 110ms, I stopped the test after. SXS / BTH.

Edit: controller is CECHZC2U (North American / Canadian model > https://www.psdevwiki.com/ps3/DualShock_3 )

[Kanuan]

Just to have it on record:

I failed once at 130ms, failed 3 times at 110ms, I stopped the test after. SXS / BTH.

Edit: controller is CECHZC2U (North American / Canadian model > https://www.psdevwiki.com/ps3/DualShock_3 )

That's waaaaay too high for a controller that supports rumble. @nefarius said that right now the driver communicates by the Control channel on bluetooth, though it can also communicate by Interrupt Out. Maybe the performance is better in the later?

[nefarius]

Bit of technical background from my side regarding the topics on compatibility and performance covered (and discovered) recently:

USB

For years (and carried over from good old SCP times) the misconception for USB communication was, that Output Reports (Rumble, LED state changes) have to travel over the Control Endpoint. This unfortunately "worked" for a majority of devices, since the ASIC in the controller apparently processed Output Reports coming in from Endpoint 0 quite happily. So that flaw was masked away by "it works therefore has to be correct". Well, it wasn't 😆 Output Reports are supposed to travel through the Interrupt Out Endpoint (like any other modern controller, Xbox, DS4 etc.). The USB Control Endpoint is not designed for high throughput (as documented in the specifications) and therefore sending multiple packets per second caused some devices to start behaving erratically in a more or less subtle manner (LED stuck blinking or on a specific value, no rumble, some even started to gain delay on Interrupt In packets).

This has been finally fixed for good in 8e11dc7 🥳

Bluetooth

Now wireless is where it really gets interesting. We recently discovered, that the devices not reacting to LED or rumble requests weren't actually unhappy about the protocol format (that was correct all along) but the send rate at which they received packets and decided to "lock up" when flooded (e.g. only 1-20ms delay between packets). Two assumptions/ideas to follow from here on:

Rate control is the saviour

We quickly hacked a timer period based rate control mechanism into the driver, which simply drops/discards/ignores new Output Reports if they're sent within a variable delay (1ms to 255ms). This appeared to work for test devices previously suffering from locking up, but causes new issues in need to be addressed: lost rumble commands. If we start to throw away packets, chances are high that Rumble OFF get tossed into the void and the controller rumbles longer than anticipated from the game or in the worst case forever until the user shuts off the controller. Before further attempting to, uh, fix this fix there's another idea that so far has been ignored.

Write to the Interrupt L2CAP Channel

Quick rundown on how the Bluetooth communication works. The controller establishes two L2CAP channels for communication (an L2CAP channel is roughly the same principal as an Endpoint on USB); HID Control for writing commands and HID Interrupt for receiving the Input Reports. Here, currently, also Output Reports are sent over the HID Control channel (it is not documented anywhere, that the same limits apply as for USB). But L2CAP channels are bidirectional so for my next trick I shall try to write the Output Reports to the HID Interrupt channel 😏 and see what happens.

Stay tuned.

[nefarius]

But L2CAP channels are bidirectional so for my next trick I shall try to write the Output Reports to the HID Interrupt channel 😏 and see what happens.

Eh, tested it, unfortunately nothing happens 😅 Worth a try though.

[nefarius]

Good/bad news; I found a vulnerable controller in my collection! 😆

CECHZC2E A1

PCSX2's rumble test can knock it right out, if deduplication is disabled, works fine when enabled:

[nefarius]

Related to #16.

[nefarius]

Just to have it on record:
I failed once at 130ms, failed 3 times at 110ms, I stopped the test after. SXS / BTH.
Edit: controller is CECHZC2U (North American / Canadian model > https://www.psdevwiki.com/ps3/DualShock_3 )

That's waaaaay too high for a controller that supports rumble. @nefarius said that right now the driver communicates by the Control channel on bluetooth, though it can also communicate by Interrupt Out. Maybe the performance is better in the later?

I'm afraid the observation is correct for our most troubled controller revisions!

The popular Arduino library has a 150ms delay requirement documented in their code. Seems to match with the test data gathered here. Oh boy, that's gonna be a tough fix 😁

[Kanuan]

Just to have this documented:

The new rate control algorithm follows more or less the proposed solution: after a OutRep is sent, new commands/OutReps being received by the driver before a minimum waiting time has passed will cause them to be saved in a buffer. The buffer holds only one packet so new ones will overwrite it. After the minimum wait time passes the buffed OutRep is sent.

There is still a bug in the algorithm. It seems that if a command/OutRep is received more-or-less at the same time a buffered OutRep is being sent than the received command will be inmediatly sent. The problem seems to occurs for some error in the timestamp calculation / buffer queue order that causes the time comparison between the new command and the last sent OutRep to result in a negative value.

[nefarius]

Fixed in v1.2.122

[Kanuan]

There is still a bug in the algorithm. It seems that if a command/OutRep is received more-or-less at the same time a buffered OutRep is being sent than the received command will be inmediatly sent. The problem seems to occurs for some error in the timestamp calculation / buffer queue order that causes the time comparison between the new command and the last sent OutRep to result in a negative value.

Just so we have this as reference for the future, this edge case issue still has not been solved, but the current state of the fix is good enough to solve the problem most of the time

[nefarius]

Yep, I was considering moving this snippet to a new issue so I can close this one to comply to my milestone strategy 😉

[nefarius]

Cool, GitHub has a feature for that! Closing here 🧹