nvWave: Dont close audio device

[feerrenrut]

Intends to replace:

• PR nvwave: Don't close the audio device unless there hasn't been any audio played for 10 seconds. #11024 nvwave: Don't close the audio device unless there hasn't been any audio played for 10 seconds.
• PR nvwave: Fix occasional exception related to close timer. #11505 nvwave: Fix occasional exception related to close timer.

Link to issue number:

Fixes #11482
Fixes #11490
Fixes #5172
Fixes #10721

Summary of the issue:

Original issues previously fixed by PR #11024 :

• As described in make the audio device still active for better response #5172, some audio drivers/hardware take a long time to open the device and/or truncate the start/end of the audio.
• As described in OneCore performance #10721 (comment), calling WaveOutOpen in the OneCore synth callback mysteriously blocks (and thus lags) for ~100 ms. Because we close the audio device on idle, we can trigger this problem. Although oneCore synth: Fix lag between utterances introduced in NVDA 2019.3. #11023 mostly fixes this, it's impossible (or at least very difficult) to resolve this completely from within the OneCore driver.
• Aside from all of this, closing and opening the audio device for rapid short utterances (e.g. rapid movement with the cursor keys or typing) doesn't seem particularly optimal. It's difficult to measure this, but I'd say mitigating this is likely to make audio performance faster/smoother.

Subsequently, occasional exceptions from nvwave, particularly when switching synthesisers.

• When using Microsoft Sound Mapper, NVDA should use the Windows default device.
• Devices becoming invalid, nvWave should fall back to Microsoft Sound Mapper
• When the configured device becomes available again, NVDA should switch back to using it.

Description of how this pull request fixes the issue:

Don't close the device at all.

• Closing and opening the audio device was originally introduced to support Remote Desktop audio, this is now better served by other solutions.
• Performance is improved by keeping it open, using a timeout means that the lag is more rare, but will still occur.

As per the discussion:
#11505 (comment)

To fix issues with current / preferred device:

• nvWave now saves the preferred device when it is constructed.
• If using a device fails, it is considered unavailable, nvWave attempts to fall back to "Microsoft Sound Mapper".
• From my testing, using "Microsoft Sound Mapper" correctly handled changing the default device (Win 10 2004). It would be helpful if others could confirm, especially on different OS versions.
• During _idleUnbuffered
  • The current device is checked to see if it matches the preferred device.
  • The available devices are polled to see if the preferred device is available, if so it switches.

Testing performed:

• Set NVDA audio device: Microsoft Sound Mapper
  • Set default device via system tray: laptop speakers
  • Set default device via system tray: bt headphones
  • Turn off bt headphones
  • Turn on bt headphones
• Set NVDA audio device: bt headphones
  • Turn off bt headphones
  • Turn on bt headphones

Logged performance of checking for preferred device.

• Check if nvWave is already using the preferred device is fast.
  • Tested code (which has since been simplified even further)
  • Average on my machine: 0.2 ms
• Check if the preferred device is available again can be slow.
  • This has to enumerate and fetch the name for each device. If there are many devices this could be exacerbated.
  • Average on my machine: 3ms
  • This may be fine as it is, since it only is hit during _idleUnbuffered and when not using the preferred device.
  • It would be possible to check this in a non-blocking way, but I'm not convinced it is worth the complication.
  • If attempting to test this specific case, you must configure NVDA to use a device that you then remove. Eg configure it to use bluetooth headphones, then turn the headphones off.

Known issues with pull request:

None

Change log entry:

Section: Bug fixes

Remove change log entry:

- The start or end of speech / sound is no longer truncated. (#5172, #10721)
  - NVDA now holds the audio device open for a short time after speech utterances, improving performance on some sound cards.

Replace it with:

- NVDA now keeps the audio device open improving performance on some sound cards (#5172, #10721)

I'm uncomfortable saying that sound is no longer truncated, this still seems to affect certain devices (EG my bluetooth headphones when no other sound is playing). I think this issue should be looked at separately.

[michaelDCurran]

Other than the change from log.debugWarning to log.exception in _feedUnbuffered_handleErrors, all is good.

[codeofdusk]

Since all review actions by @michaelDCurran have been completed, do you now plan to merge this PR?

[feerrenrut]

@codeofdusk Yes, I plan to merge this in shortly.

[lukaszgo1]

I'm getting a lot of errors from garbageHandler about unreachable objects, especially during say all after this got merged.

sample log:

ERROR - garbageHandler.notifyObjectDeletion (22:33:48.098) - MainThread (756):
Garbage collector has found one or more unreachable objects. See further warnings for specific objects.
Stack trace:
  File "nvda.pyw", line 215, in <module>
  File "core.pyc", line 550, in main
  File "wx\core.pyc", line 2134, in MainLoop
  File "gui\__init__.pyc", line 1050, in Notify
  File "core.pyc", line 520, in run
  File "queueHandler.pyc", line 88, in pumpAll
  File "queueHandler.pyc", line 55, in flushQueue
  File "sayAllHandler.pyc", line 146, in nextLine
  File "textInfos\offsets.pyc", line 615, in move
  File "displayModel.pyc", line 414, in _getStoryLength
  File "baseObject.pyc", line 42, in __get__
  File "baseObject.pyc", line 146, in _getPropertyViaCache
  File "displayModel.pyc", line 319, in _get__storyFieldsAndRects
  File "displayModel.pyc", line 204, in getWindowTextInRect
  File "displayModel.pyc", line 34, in wcharToInt
  File "garbageHandler.pyc", line 23, in __del__
  File "garbageHandler.pyc", line 63, in notifyObjectDeletion
  File "logging\__init__.pyc", line 1407, in error
  File "logHandler.pyc", line 160, in _log
  File "logging\__init__.pyc", line 1514, in _log
  File "logging\__init__.pyc", line 1524, in handle
  File "logging\__init__.pyc", line 1586, in callHandlers
  File "logHandler.pyc", line 279, in handle
  File "nvwave.pyc", line 567, in playWaveFile
  File "nvwave.pyc", line 490, in __del__
  File "garbageHandler.pyc", line 23, in __del__
  File "garbageHandler.pyc", line 63, in notifyObjectDeletion
WARNING - garbageHandler.notifyObjectDeletion (22:33:48.108) - MainThread (756):
Deleting unreachable object <nvwave.WavePlayer object at 0x0C4F0EF0>
WARNING - garbageHandler.notifyObjectDeletion (22:33:48.108) - MainThread (756):
Deleting unreachable object <nvwave.WavePlayer object at 0x0C6C2F10>
ERROR - garbageHandler.notifyObjectDeletion (22:33:48.078) - MainThread (756):
Garbage collector has found one or more unreachable objects. See further warnings for specific objects.
Stack trace:
  File "nvda.pyw", line 215, in <module>
  File "core.pyc", line 550, in main
  File "wx\core.pyc", line 2134, in MainLoop
  File "gui\__init__.pyc", line 1050, in Notify
  File "core.pyc", line 520, in run
  File "queueHandler.pyc", line 88, in pumpAll
  File "queueHandler.pyc", line 55, in flushQueue
  File "sayAllHandler.pyc", line 146, in nextLine
  File "textInfos\offsets.pyc", line 615, in move
  File "displayModel.pyc", line 414, in _getStoryLength
  File "baseObject.pyc", line 42, in __get__
  File "baseObject.pyc", line 146, in _getPropertyViaCache
  File "displayModel.pyc", line 319, in _get__storyFieldsAndRects
  File "displayModel.pyc", line 204, in getWindowTextInRect
  File "displayModel.pyc", line 34, in wcharToInt
  File "garbageHandler.pyc", line 23, in __del__
  File "garbageHandler.pyc", line 63, in notifyObjectDeletion
WARNING - garbageHandler.notifyObjectDeletion (22:33:48.518) - MainThread (756):
Deleting unreachable object <NVDAObjects.IAccessible.ContentGenericClient object at 0x0C525D30>
WARNING - garbageHandler.notifyObjectDeletion (22:33:48.518) - MainThread (756):
Deleting unreachable object <POINTER(IAccessible) ptr=0xa8b3df8 at c551490>
WARNING - garbageHandler.notifyObjectDeletion (22:33:48.538) - MainThread (756):
Deleting unreachable object <nvwave.WavePlayer object at 0x0C6C2B50>
ERROR - garbageHandler._collectionCallback (22:33:48.518) - MainThread (756):
Found at least 4 unreachable objects in run

I haven't created an issue since I don't have concrete STR.

[michaelDCurran]

@lukaszgo1 A few questions:

• Do you have a specific sayAll profile set up?
• What synth are you using?
• Do you have any add-ons installed? Especially ones that might play audio for particular controls or formatting?
• Does it perhaps happen directly after another error where the NVDA error sound is played?
• Note that this pr most likely did not directly cause these extra reference cycles, but did fix an issue where WavePlayer reference cycles were not being tracked. Thus, this bug has probably always occurred. Either we will track it down before 20.3 or we'll consider suppressing some or all of these garbage handler messages for official releases. But they are very useful in snapshots / betas.

[lukaszgo1]

@michaelDCurran wrote:

* Do you have a specific sayAll profile set up?

No, I don't

* What synth are you using?

eSpeak Polish voice, variant Max rate 56 with rate boost enabled.

* Do you have any add-ons installed? Especially ones that might play audio for particular controls or formatting?

Yes, none of them plays any sounds though. All my add-ons just for completeness:

addonUpdater
charInfo
classicSelection
columnsReview
emoticons
latex-access
latex_access_nvda_pl
latex-access_py3
Mozilla
noBeepsSpeechMode
NotepadPlusPlus
ocr
openTween
percentage checker
placeMarkers
remote
reportPasswords
synthRingSettingsSelector
unicornNVDA
winWizard
wordCount

* Does it perhaps happen directly after another error where the NVDA error sound is played?

No, error sound plays twice when the info from my previous commend is logged.