[wdmaudiodev] Re: Excessive AVStream Driver Filter Creation

  • From: "Gary Daniels" <dmarc-noreply@xxxxxxxxxxxxx> (Redacted sender "Gary.Daniels" for DMARC)
  • To: "wdmaudiodev@xxxxxxxxxxxxx" <wdmaudiodev@xxxxxxxxxxxxx>
  • Date: Tue, 6 Aug 2019 20:04:56 +0000

Hi Cobey,

Can you try out the latest insiders build?

I recently did some work in AudioEndpointBuilder to make it more efficient and 
those changes are currently available in the latest insiders build. I suspect 
that it will help with the problems you're seeing. Prior to my change any 
interface state change or jack notification event would trigger 
AudioEndpointBuilder to reprocess every endpoint in the system. If you have 11 
endpoints and 10 interfaces change state, it would do 110 endpoints worth of 
processing.

With the current insiders build, it will only process the endpoint(s) 
associated to the interface that changed state. 10 interfaces changing state 
only results in 10 endpoints worth of processing. This also dramatically 
reduces the number of notifications published by AudioEndpoint builder. The 
Realtek process, and others, are listening to those notifications and using 
them to trigger work. That is likely why you're seeing activity originating 
from that process.

This new strategy may be slower for some systems with only a couple audio 
endpoints. It takes a fair amount of work to identify the audio endpoints 
associated to the interface that triggered the notification. However, it should 
be dramatically more performant for systems like yours with many endpoints.

If this does not fix the issue it will be helpful to have AudioEndpointBuilder 
logs from the latest insiders build to investigate.

Matthew has some scripts available on his blog for collecting these logs: 
https://matthewvaneerde.wordpress.com/2017/01/09/collecting-audio-logs-the-old-fashioned-way/

  1.
start the script
  2.
attach your peripheral
  3.
wait until the processing completes
  4.
stop the script and share the .zip file with me

Thanks,
-Gary Daniels
Microsoft audio silicon
gary.daniels at microsoft



Sent from Outlook<http://aka.ms/weboutlook>

________________________________
From: wdmaudiodev-bounce@xxxxxxxxxxxxx <wdmaudiodev-bounce@xxxxxxxxxxxxx> on 
behalf of Gatos, Cobey <cgatos@xxxxxxxxxxxxxxxxx>
Sent: Tuesday, July 23, 2019 6:56 AM
To: wdmaudiodev@xxxxxxxxxxxxx <wdmaudiodev@xxxxxxxxxxxxx>
Subject: [wdmaudiodev] Re: Excessive AVStream Driver Filter Creation

I have opened a support case (SRX1477593747ID), Is there anything else I can 
do? Do you have any ideas for possible work-arounds?


On Jul 11, 2019, at 11:29 AM, Matthew van Eerde (Redacted sender 
"Matthew.van.Eerde" for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx<mailto:dmarc-noreply@xxxxxxxxxxxxx>> wrote:

If you want to expedite it and get status updates you could open a support 
case. Give them bug number 22548754.

________________________________
From: wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx
<wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx>> on 
behalf of Gatos, Cobey 
<cgatos@xxxxxxxxxxxxxxxxx<mailto:cgatos@xxxxxxxxxxxxxxxxx>>
Sent: Wednesday, July 10, 2019 7:36:40 PM
To: wdmaudiodev@xxxxxxxxxxxxx<mailto:wdmaudiodev@xxxxxxxxxxxxx
<wdmaudiodev@xxxxxxxxxxxxx<mailto:wdmaudiodev@xxxxxxxxxxxxx>>
Subject: [wdmaudiodev] Re: Excessive AVStream Driver Filter Creation

Matthew,

Do you know how long I can expect to wait for this problem report to get some 
attention, and if there is anything I can do to help move it along?

Thanks.


On Jul 3, 2019, at 12:15 PM, Matthew van Eerde (Redacted sender 
"Matthew.van.Eerde" for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx<mailto:dmarc-noreply@xxxxxxxxxxxxx>> wrote:

Thanks for filing the problem report.

________________________________
From: wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx
<wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx>> on 
behalf of Gatos, Cobey 
<cgatos@xxxxxxxxxxxxxxxxx<mailto:cgatos@xxxxxxxxxxxxxxxxx>>
Sent: Wednesday, July 3, 2019 6:49:53 AM
To: wdmaudiodev@xxxxxxxxxxxxx<mailto:wdmaudiodev@xxxxxxxxxxxxx>
Subject: [wdmaudiodev] Re: Excessive AVStream Driver Filter Creation

I have filed a problem report in the Feedback Hub describing this problem.

Here is the link:

https://aka.ms/AA5i4tj

Thanks.


On May 31, 2019, at 12:14 PM, Gatos, Cobey 
<cgatos@xxxxxxxxxxxxxxxxx<mailto:cgatos@xxxxxxxxxxxxxxxxx>> wrote:


I wanted to bring up the MIDI issue that I observed which I believe is related 
to the excessive filter creation.  You can read my description of the problem 
earlier in this thread.

I logged an event when my driver receives MIDI CC messages. During the call 
from which my test application will receive a MMSYSERR_NODRIVER error, a MIDI 
reset call is made, which generates MIDI CC messages and causes the driver to 
log the event. I ran two test scenarios - one where my test application sent 
multiple MIDI Note On messages, and one where it sent multiple sysex messages. 
After more sending more than 1000 messages successfully, my test application 
received an error. The driver itself did not generate or receive any errors, 
the device was not disconnected, and subsequent attempts to send MIDI work 
fine. Here are the logs:

https://www.dropbox.com/s/jbgh6tb0jw2g9ts/MIDIFail.zip?dl=0<https://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.dropbox.com%2Fs%2Fjbgh6tb0jw2g9ts%2FMIDIFail.zip%3Fdl%3D0&data=02%7C01%7CGary.Daniels%40microsoft.com%7Cc7dd0aa8e04349e92fe208d70f75a450%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636994870295491327&sdata=Q6wSpBOwAsOiy2xwTMvmdi8VJkD0AWnD6ydSvxah8So%3D&reserved=0>

Does the call stack shed any light on the cause of this problem?



On May 29, 2019, at 6:41 PM, Matthew van Eerde (Redacted sender 
"Matthew.van.Eerde" for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx<mailto:dmarc-noreply@xxxxxxxxxxxxx>> wrote:

Nope, I’m out of ideas. At this point you should file a problem report in 
Feedback Hub with logs of the problem in action.

Once you’ve filed the bug, send me a link.

https://matthewvaneerde.wordpress.com/2016/09/26/report-problems-with-logs-and-suggest-features-with-the-feedback-hub/<https://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fmatthewvaneerde.wordpress.com%2F2016%2F09%2F26%2Freport-problems-with-logs-and-suggest-features-with-the-feedback-hub%2F&data=02%7C01%7CGary.Daniels%40microsoft.com%7Cc7dd0aa8e04349e92fe208d70f75a450%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636994870295491327&sdata=D5dlOjBX6BtS6ug5bjqgF0CDn0FZ%2FNHBQ1UwS9j%2FWLo%3D&reserved=0>

________________________________

From: wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx
<wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx>> on 
behalf of Gatos, Cobey 
<cgatos@xxxxxxxxxxxxxxxxx<mailto:cgatos@xxxxxxxxxxxxxxxxx>>
Sent: Wednesday, May 29, 2019 3:36:55 PM
To: wdmaudiodev@xxxxxxxxxxxxx<mailto:wdmaudiodev@xxxxxxxxxxxxx>
Subject: [wdmaudiodev] Re: Excessive AVStream Driver Filter Creation

I added an event for register and an event for enable. As the log shows, the 
driver only makes these calls at load time. I could not find anywhere else in 
the driver where these calls are made.

For the following log, I enabled all 11 audio devices the driver will expose, 
and I also enabled MIDI. I disabled the other audio devices besides my own. The 
log once again is a result of connecting my device, without attempting to 
generate any audio or MIDI data. For some reason, the strings for my new events 
did not show up - the event labelled 5/14 is the register event, and the other 
one is the enabled event. I also added a disable event, but this is not called. 
I would not expect it to be called until the device is disconnected.

https://www.dropbox.com/s/wpykqz4gddore28/FilterCreateClose3.zip?dl=0<https://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.dropbox.com%2Fs%2Fwpykqz4gddore28%2FFilterCreateClose3.zip%3Fdl%3D0&data=02%7C01%7CGary.Daniels%40microsoft.com%7Cc7dd0aa8e04349e92fe208d70f75a450%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636994870295501327&sdata=lKlg4FGmkIRnDK733J%2B3VXZzm4WcRUuu78NerIoPQV0%3D&reserved=0>

Any other ideas on where all the device arrival notifications are coming from?




On May 28, 2019, at 6:18 PM, Matthew van Eerde (Redacted sender 
"Matthew.van.Eerde" for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx<mailto:dmarc-noreply@xxxxxxxxxxxxx>> wrote:

The ETW event in your filter creation and close callback tells us WHO is 
opening your device – Realtek, and the Audio Endpoint Builder service.

The call stack from that event tells us WHY – because there was an add-device 
callback or a remove-device callback.

To figure out why there was an add-device callback or a remove-device callback, 
we have to go one step back in the past. Can you find all the code in your 
driver that registers and/or enables KSCATEGORY_AUDIO interfaces, and add an 
ETW event there too? Then update the .wprp to listen for that event and let’s 
see what the call stack is when that event is logged.

From: Gatos, Cobey<mailto:cgatos@xxxxxxxxxxxxxxxxx>
Sent: Tuesday, May 28, 2019 2:13 PM
To: wdmaudiodev@xxxxxxxxxxxxx<mailto:wdmaudiodev@xxxxxxxxxxxxx>
Subject: [wdmaudiodev] Re: Excessive AVStream Driver Filter Creation

I disabled the other devices, and I observed that the number of filter create 
calls to my driver diminished by a factor of 2. However there were still plenty 
of arrival notifications. (I am surprised that the presence of other devices 
effects the number of calls into my driver.)

To simplify things, I disabled MIDI, and I disabled the stereo pair audio 
devices, so that the driver would expose only a multi-channel in and 
multi-channel out audio device. Leaving the other audio devices on my system 
disabled, I recorded the following etl log.

https://www.dropbox.com/s/u7s9bxy8znpmxce/FilterCreateClose2.zip?dl=0<https://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.dropbox.com%2Fs%2Fu7s9bxy8znpmxce%2FFilterCreateClose2.zip%3Fdl%3D0&data=02%7C01%7CGary.Daniels%40microsoft.com%7Cc7dd0aa8e04349e92fe208d70f75a450%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636994870295501327&sdata=tnZIALfeGLFw7UtNNrve0TdViu5WXj1iDUgH1g6pW20%3D&reserved=0>

Can you give me any clues on now my driver would be creating multiple device 
arrival notifications?

Cobey


On May 24, 2019, at 3:05 PM, Matthew van Eerde (Redacted sender 
"Matthew.van.Eerde" for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx<mailto:dmarc-noreply@xxxxxxxxxxxxx>> wrote:


Let’s start by figuring out the source of the arrival and removal notifications.

Go into Device Manager > Sound, video and game controllers.

Disable all the other devices but your own and see if the problem still happens.

If so, your driver is the source of the notifications.

If not, you can re-enable the other devices, one by one, until the problem 
recurs. That device is the source of the notifications.

<70FB68EF19394D21BA098C3C24E7324A.png>
From: wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx
<wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx>> on 
behalf of Gatos, Cobey 
<cgatos@xxxxxxxxxxxxxxxxx<mailto:cgatos@xxxxxxxxxxxxxxxxx>>
Sent: Friday, May 24, 2019 11:50:44 AM
To: wdmaudiodev@xxxxxxxxxxxxx<mailto:wdmaudiodev@xxxxxxxxxxxxx>
Subject: [wdmaudiodev] Re: Excessive AVStream Driver Filter Creation


I found some code that did a single disable during the startup process, 
followed shortly by an enable. This disable only occurred once early on. I 
removed the disable call, and it did not appreciably change the behavior. Is 
there anything else the driver might be doing that might contribute to the 
problem?

I have another issue which I believe is related to this problem. If, during 
this period of multiple filter create and close calls, I repeatedly send MIDI 
messages to the driver, I will eventually receive an error return from Windows, 
despite the driver not detecting or returning any errors. If I wait 5 - 10 
minutes after connecting the device for these filter calls to stop happening, 
the error does not occur. Also, if I disable audio in the driver so that only 
MIDI is exposed, the error does not occur. I may successfully send 100 or 1000 
messages before seeing an error.

The error value I receive is MMSYSERR_NODRIVER. When I ran the MIDI test by 
repeatedly sending sysex messages using midiOutLongMsg(), during the call to 
midiOutLongMsg that returned the error, the driver would receive a set of MIDI 
messages that correspond to those sent after calling midiOutReset(), despite my 
code not calling that function. I was also able to reproduce the 
MMSYSERR_NODRIVER error by repeatedly calling midiOutPrepareHeader() and 
midiOutUnprepareHeader(), without actually sending any MIDI data. During this 
test, the driver received calls to create a filter and MIDI pin (corresponding 
to opening the MIDI device), but did not receive any data to send, and did not 
generate any errors. I have also duplicated the error with repeated calls to 
midiOutShortMsg().

It is possible this problem is unrelated and represents a separate issue, but I 
suspect it may be related.

Cobey





On May 24, 2019, at 11:52 AM, Matthew van Eerde (Redacted sender 
"Matthew.van.Eerde" for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx<mailto:dmarc-noreply@xxxxxxxxxxxxx>> wrote:


About half of it is RtkNGUI64.exe and about half of it is the 
AudioEndpointBuilder service (with some other processes too.)

It looks like there is a whole lot of device arrival and removal notifications 
going on. Are you enabling and disabling your KSCATEGORY_AUDIO interface?

<866945E8B46741A4BE4914044A7C9E5A.png>
From: wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx
<wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx>> on 
behalf of Gatos, Cobey 
<cgatos@xxxxxxxxxxxxxxxxx<mailto:cgatos@xxxxxxxxxxxxxxxxx>>
Sent: Friday, May 24, 2019 8:00:50 AM
To: wdmaudiodev@xxxxxxxxxxxxx<mailto:wdmaudiodev@xxxxxxxxxxxxx>
Subject: [wdmaudiodev] Re: Excessive AVStream Driver Filter Creation




As suggested, I have created a log of the Create and Close calls in my driver. 
I have posted the .etl file here:



https://www.dropbox.com/s/f6hiicanmwm8tq9/FilterCreateClose.zip?dl=0<https://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.dropbox.com%2Fs%2Ff6hiicanmwm8tq9%2FFilterCreateClose.zip%3Fdl%3D0&data=02%7C01%7CGary.Daniels%40microsoft.com%7Cc7dd0aa8e04349e92fe208d70f75a450%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636994870295511316&sdata=zrkIs5psq11Fum3fUvS6Eo0n3x8FPy1DElI9lV5V0b0%3D&reserved=0>



To generate this log, I just connected my device to the computer. I did not 
open any audio applications. The driver includes a MIDI filter factory, and 
calls create and close MIDI filters are included in the log.



Thanks.



Cobey





On May 15, 2019, at 1:33 PM, Matthew van Eerde (Redacted sender 
"Matthew.van.Eerde" for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx<mailto:dmarc-noreply@xxxxxxxxxxxxx>> wrote:


Log an ETW event from your Create and Close callbacks.
Author a .wprp which listens for these events and grabs stacks at the time they 
happen (see 
https://blogs.msdn.microsoft.com/matthew_van_eerde/2018/11/12/what-api-is-being-used-to-play-or-record-audio/<https://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fblogs.msdn.microsoft.com%2Fmatthew_van_eerde%2F2018%2F11%2F12%2Fwhat-api-is-being-used-to-play-or-record-audio%2F&data=02%7C01%7CGary.Daniels%40microsoft.com%7Cc7dd0aa8e04349e92fe208d70f75a450%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636994870295511316&sdata=q7F7syUvMzYC%2FTQQLs3%2FCLW0I7HMCm%2F7VJ3Ub2utjTI%3D&reserved=0>)
Record the 2000 calls into an .etl.
Share the .etl.
This will reveal who is instantiating the filters (and, hopefully, why.)



<866945E8B46741A4BE4914044A7C9E5A.png>
From: wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx
<wdmaudiodev-bounce@xxxxxxxxxxxxx<mailto:wdmaudiodev-bounce@xxxxxxxxxxxxx>> on 
behalf of Gatos, Cobey 
<cgatos@xxxxxxxxxxxxxxxxx<mailto:cgatos@xxxxxxxxxxxxxxxxx>>
Sent: Wednesday, May 15, 2019 10:29:38 AM
To: wdmaudiodev@xxxxxxxxxxxxx<mailto:wdmaudiodev@xxxxxxxxxxxxx>
Subject: [wdmaudiodev] Excessive AVStream Driver Filter Creation


I have an AVStream driver for a 10 x 8 USB audio device. The driver exposes 
both multi-channel input and output audio devices to Windows, and additionally 
stereo pair audio devices for each available audio channel pair. There is a 
separate filter factory for each of these (11 total).

When I plug my device in, the driver receives hundreds of filter Create and 
Close calls - on one of my machines the number approaches 2000 create calls. 
This happens without any audio applications open, and without any pins being 
created. These calls can continue for a period of 5 - 10 minutes before they 
diminish in frequency and stop. When the calls stop, there will be 50 - 60 
filters remaining open, and they remain open until I disconnect the device, at 
which point they will all be closed. If the driver exposes only multi-channel 
input and output devices (2 filter factories), the number of filter Create 
calls will decrease to 60 - 80.

I am curious as to why this is happening. Is this normal behavior for Windows? 
I have examined the filter using KS Studio, and compared it to filters created 
by Windows USB audio class driver, and I am not noticing any significant issues 
or differences.

Thanks.

Cobey******************

WDMAUDIODEV addresses:
Post message: mailto:wdmaudiodev@xxxxxxxxxxxxx
Subscribe:    mailto:wdmaudiodev-request@xxxxxxxxxxxxx?subject=subscribe
Unsubscribe:  mailto:wdmaudiodev-request@xxxxxxxxxxxxx?subject=unsubscribe
Moderator:    mailto:wdmaudiodev-moderators@xxxxxxxxxxxxx

URL to WDMAUDIODEV page:
https://nam06.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.wdmaudiodev.com%2F&amp;data=01%7C01%7Cmatthew.van.eerde%40microsoft.com%7Ccb8b9c4726114e89a65a08d6d95aff76%7C72f988bf86f141af91ab2d7cd011db47%7C1&amp;sdata=XdiNC4umPLq%2BCIQqCbEuVRrltNfQ1YPI%2FHvTUXnT3zk%3D&amp;reserved=0<https://nam06.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.wdmaudiodev.com%2F&data=02%7C01%7CGary.Daniels%40microsoft.com%7Cc7dd0aa8e04349e92fe208d70f75a450%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636994870295521309&sdata=rEBj8fDBRSlZAZsDbiB72fyVMCgtkNHTPml0SO7%2FA4A%3D&reserved=0>

Other related posts: