From c5106115bf09e00a3a0b370d287950c8294b038f Mon Sep 17 00:00:00 2001 From: Mack Straight Date: Sat, 3 Oct 2026 13:46:48 -0400 Subject: [PATCH] test: let the endpoint builder settle after the race, and watch it recovery-after-kill failed on every build once the race ran right before it (6 of 6 runs with 16 pairs). The race restarts the host ten times in about 35 s, and each restart disables and re-enables 32 endpoints' worth of KS interfaces, more than Windows' audio endpoint builder can process as it happens. It keeps working through that for about 15 s after the race (12 s of its CPU), tearing down and rebuilding SAR endpoints one at a time while their interfaces stay enabled. kill-host started 0.5 s after the race, so the backlog ran into recovery, whose streams stalled in Activate (the 4 s GetDeviceInterfacePath2 retry) and Initialize (serialized behind it, up to 20 s) or were invalidated. Wait for the endpoint builder to go idle after the race (under 100 ms of CPU per second for three seconds, at most two minutes) and record how long that took as settle-after-race. With the wait, recovery passes; kill and recovery without a race before them never showed the problem. SarTest watch, which found this, runs from before the race through recovery: it logs every change in which SAR KS interfaces are enabled, every endpoint state change MMDevAPI reports, seconds in which the endpoint builder or audio service used 50 ms of CPU or more, and with --probe, each change in whether the SAR filters can be opened. Invoke-SarTest also takes -PostRaceDelaySeconds for extra idle time. Co-Authored-By: Claude Opus 5.5 --- SarTest/SarTest.cpp | 20 ++ SarTest/SarTest.vcxproj | 4 +- SarTest/install.cpp | 27 ++ SarTest/install.h | 2 + SarTest/watch.cpp | 453 ++++++++++++++++++++++++++++++++++ SarTest/watch.h | 42 ++++ tools/test/Invoke-SarTest.ps1 | 73 +++++- tools/test/README.md | 18 ++ 8 files changed, 637 insertions(+), 2 deletions(-) create mode 100644 SarTest/watch.cpp create mode 100644 SarTest/watch.h diff --git a/SarTest/SarTest.cpp b/SarTest/SarTest.cpp index 5321622..ee49d78 100644 --- a/SarTest/SarTest.cpp +++ b/SarTest/SarTest.cpp @@ -21,6 +21,7 @@ #include "install.h" #include "asiohost.h" #include "wasapi.h" +#include "watch.h" #include "clockstats.h" #include @@ -66,6 +67,11 @@ int usage() " Watch the audio sessions on every active playback endpoint and\n" " report which processes played and how loud; with --process, fail\n" " unless that process reached --min-peak (default 0.01).\n" + " SarTest watch [--duration S] [--stop-file ] [--poll MS] [--probe MS]\n" + " Log every change in which SAR KS interfaces are enabled and every\n" + " endpoint state change, with timestamps, until S seconds pass or\n" + " the stop file exists. --probe MS also opens every enabled SAR filter\n" + " that often and logs each change in the result.\n" "\n" "Layout options: --endpoints N (playback/recording pairs, default 2)\n" " --channels C (per endpoint, default 2) --prefix \n" @@ -855,6 +861,18 @@ int cmdMeter(const Args& args) return rc; } +int cmdWatch(const Args& args) +{ + WatchOptions options; + + options.durationSeconds = args.getDouble(L"duration", 60.0); + options.stopFile = args.get(L"stop-file", L""); + options.pollMs = args.getInt(L"poll", 20); + options.probeMs = args.getInt(L"probe", 0); + writeResults(args, runWatch(options)); + return 0; +} + } // namespace int wmain(int argc, wchar_t **argv) @@ -896,6 +914,8 @@ int wmain(int argc, wchar_t **argv) rc = cmdEndpointNames(args); } else if (args.command == L"meter") { rc = cmdMeter(args); + } else if (args.command == L"watch") { + rc = cmdWatch(args); } else { rc = usage(); } diff --git a/SarTest/SarTest.vcxproj b/SarTest/SarTest.vcxproj index b68c529..6c1d73c 100644 --- a/SarTest/SarTest.vcxproj +++ b/SarTest/SarTest.vcxproj @@ -67,7 +67,7 @@ Console true - setupapi.lib;newdev.lib;shlwapi.lib;shell32.lib;ole32.lib;oleaut32.lib;uuid.lib;advapi32.lib;kernel32.lib;user32.lib;%(AdditionalDependencies) + setupapi.lib;cfgmgr32.lib;newdev.lib;shlwapi.lib;shell32.lib;ole32.lib;oleaut32.lib;uuid.lib;advapi32.lib;kernel32.lib;user32.lib;%(AdditionalDependencies) @@ -97,12 +97,14 @@ + + diff --git a/SarTest/install.cpp b/SarTest/install.cpp index 0d3986b..9ea15e4 100644 --- a/SarTest/install.cpp +++ b/SarTest/install.cpp @@ -17,6 +17,7 @@ #include "install.h" #include +#include #include #include #include @@ -156,6 +157,32 @@ static int visitSarDeviceNodes(bool remove) return found; } +std::wstring sarDeviceInstanceId() +{ + HDEVINFO set = SetupDiGetClassDevsW(&kMediaClassGuid, nullptr, nullptr, DIGCF_PRESENT); + std::wstring result; + + if (set == INVALID_HANDLE_VALUE) { + return result; + } + + SP_DEVINFO_DATA data = {}; + + data.cbSize = sizeof(data); + + for (DWORD i = 0; result.empty() && SetupDiEnumDeviceInfo(set, i, &data); ++i) { + wchar_t id[MAX_DEVICE_ID_LEN] = {}; + + if (hasSarHardwareId(set, &data) && + SetupDiGetDeviceInstanceIdW(set, &data, id, MAX_DEVICE_ID_LEN, nullptr)) { + result = id; + } + } + + SetupDiDestroyDeviceInfoList(set); + return result; +} + bool deviceNodeExists() { return visitSarDeviceNodes(false) > 0; diff --git a/SarTest/install.h b/SarTest/install.h index 748dd86..2b0a1c4 100644 --- a/SarTest/install.h +++ b/SarTest/install.h @@ -37,6 +37,8 @@ bool writeDriverConfig( // Software device node for the SAR driver, matching the INF's hardware ID. bool deviceNodeExists(); +// Device instance ID of the present SAR device node; empty if there is none. +std::wstring sarDeviceInstanceId(); bool createDeviceNode(); bool removeDeviceNode(); diff --git a/SarTest/watch.cpp b/SarTest/watch.cpp new file mode 100644 index 0000000..eb8933f --- /dev/null +++ b/SarTest/watch.cpp @@ -0,0 +1,453 @@ +// SynchronousAudioRouter +// Copyright (C) 2026 Mackenzie Straight +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with SynchronousAudioRouter. If not, see . + +#include "watch.h" +#include "install.h" + +#include +#include +#include +#include +#include + +namespace SarTest { + +namespace { + +// KSCATEGORY_AUDIO: every SAR wave and topology filter is registered in it. +const GUID kKsCategoryAudio = + { 0x6994AD04, 0x93EF, 0x11D0, { 0xA3, 0xCC, 0x00, 0xA0, 0xC9, 0x22, 0x31, 0x96 } }; + +const char *stateName(DWORD state) +{ + switch (state) { + case DEVICE_STATE_ACTIVE: return "active"; + case DEVICE_STATE_DISABLED: return "disabled"; + case DEVICE_STATE_NOTPRESENT: return "notpresent"; + case DEVICE_STATE_UNPLUGGED: return "unplugged"; + default: return "unknown"; + } +} + +// The reference string at the end of an interface path, which for SAR is +// "___[_topology]". +std::string referenceString(const std::wstring& path) +{ + auto slash = path.find_last_of(L'\\'); + + return narrow(slash == std::wstring::npos ? path : path.substr(slash + 1)); +} + +// Reference string -> interface path of every enabled SAR KS interface. +std::map enabledInterfacePaths(const std::wstring& instanceId) +{ + std::map result; + ULONG length = 0; + + if (CM_Get_Device_Interface_List_SizeW(&length, (LPGUID)&kKsCategoryAudio, + (DEVINSTID_W)instanceId.c_str(), + CM_GET_DEVICE_INTERFACE_LIST_PRESENT) != CR_SUCCESS || length == 0) { + return result; + } + + std::vector buffer(length + 1, L'\0'); + + if (CM_Get_Device_Interface_ListW((LPGUID)&kKsCategoryAudio, + (DEVINSTID_W)instanceId.c_str(), buffer.data(), length, + CM_GET_DEVICE_INTERFACE_LIST_PRESENT) != CR_SUCCESS) { + return result; + } + + for (const wchar_t *p = buffer.data(); *p; p += wcslen(p) + 1) { + result[referenceString(p)] = p; + } + + return result; +} + +std::set enabledInterfaces(const std::wstring& instanceId) +{ + std::set result; + + for (const auto& pair : enabledInterfacePaths(instanceId)) { + result.insert(pair.first); + } + + return result; +} + +// CPU time used so far by the process hosting a service (its own svchost on +// machines with enough memory), so a busy endpoint builder shows up even when +// it changes nothing anyone can observe. +class ServiceCpu +{ +public: + explicit ServiceCpu(const wchar_t *service) + { + SC_HANDLE scm = OpenSCManagerW(nullptr, nullptr, SC_MANAGER_CONNECT); + SC_HANDLE svc = scm ? OpenServiceW(scm, service, SERVICE_QUERY_STATUS) : nullptr; + SERVICE_STATUS_PROCESS status = {}; + DWORD needed = 0; + + if (svc && QueryServiceStatusEx(svc, SC_STATUS_PROCESS_INFO, + (LPBYTE)&status, sizeof(status), &needed)) { + _process = OpenProcess(PROCESS_QUERY_LIMITED_INFORMATION, FALSE, + status.dwProcessId); + } + + if (svc) { + CloseServiceHandle(svc); + } + + if (scm) { + CloseServiceHandle(scm); + } + + _last = totalMs(); + } + + ~ServiceCpu() + { + if (_process) { + CloseHandle(_process); + } + } + + // Milliseconds of CPU used since the previous call. + double delta() + { + double now = totalMs(); + double result = now - _last; + + _last = now; + return result; + } + +private: + double totalMs() + { + FILETIME created, exited, kernel, user; + + if (!_process || !GetProcessTimes(_process, &created, &exited, &kernel, &user)) { + return 0.0; + } + + auto ms = [](const FILETIME& ft) { + return (((ULONGLONG)ft.dwHighDateTime << 32) | ft.dwLowDateTime) / 10000.0; + }; + + return ms(kernel) + ms(user); + } + + HANDLE _process = nullptr; + double _last = 0.0; +}; + +// Opens a KS filter instance the way a client does, and closes it again. +DWORD probeFilter(const std::wstring& path) +{ + HANDLE handle = CreateFileW(path.c_str(), GENERIC_READ | GENERIC_WRITE, + 0, nullptr, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, nullptr); + + if (handle == INVALID_HANDLE_VALUE) { + return GetLastError(); + } + + CloseHandle(handle); + return ERROR_SUCCESS; +} + +struct WatchEvent +{ + double ms; + std::string kind; + std::string subject; + std::string detail; +}; + +class EndpointWatcher: public IMMNotificationClient +{ +public: + EndpointWatcher(double originMs, IMMDeviceEnumerator *enumerator) + : _originMs(originMs), _enumerator(enumerator) + { + IMMDeviceCollection *devices = nullptr; + + // Names of every endpoint Windows knows, present or not, so events + // can be logged by name. + if (SUCCEEDED(_enumerator->EnumAudioEndpoints( + eAll, DEVICE_STATEMASK_ALL, &devices))) { + UINT count = 0; + + devices->GetCount(&count); + + for (UINT i = 0; i < count; ++i) { + IMMDevice *device = nullptr; + + if (SUCCEEDED(devices->Item(i, &device))) { + LPWSTR id = nullptr; + + if (SUCCEEDED(device->GetId(&id))) { + _names[id] = deviceName(device); + CoTaskMemFree(id); + } + + device->Release(); + } + } + + devices->Release(); + } + } + + ULONG STDMETHODCALLTYPE AddRef() override { return 1; } + ULONG STDMETHODCALLTYPE Release() override { return 1; } + + HRESULT STDMETHODCALLTYPE QueryInterface(REFIID riid, void **ppv) override + { + if (riid == IID_IUnknown || riid == __uuidof(IMMNotificationClient)) { + *ppv = static_cast(this); + return S_OK; + } + + *ppv = nullptr; + return E_NOINTERFACE; + } + + HRESULT STDMETHODCALLTYPE OnDeviceStateChanged(LPCWSTR id, DWORD state) override + { + record("endpoint", id, stateName(state)); + return S_OK; + } + + HRESULT STDMETHODCALLTYPE OnDeviceAdded(LPCWSTR id) override + { + record("endpoint", id, "added"); + return S_OK; + } + + HRESULT STDMETHODCALLTYPE OnDeviceRemoved(LPCWSTR id) override + { + record("endpoint", id, "removed"); + return S_OK; + } + + HRESULT STDMETHODCALLTYPE OnDefaultDeviceChanged(EDataFlow, ERole, LPCWSTR) override + { + return S_OK; + } + + HRESULT STDMETHODCALLTYPE OnPropertyValueChanged(LPCWSTR, const PROPERTYKEY) override + { + return S_OK; + } + + void addEvent(const WatchEvent& event) + { + std::lock_guard lock(_mutex); + + _events.push_back(event); + } + + std::vector events() + { + std::lock_guard lock(_mutex); + + return _events; + } + +private: + static std::string deviceName(IMMDevice *device) + { + IPropertyStore *store = nullptr; + std::string name; + + if (SUCCEEDED(device->OpenPropertyStore(STGM_READ, &store))) { + PROPVARIANT value; + + PropVariantInit(&value); + + if (SUCCEEDED(store->GetValue(PKEY_Device_DeviceDesc, &value)) && + value.vt == VT_LPWSTR && value.pwszVal) { + name = narrow(value.pwszVal); + } + + PropVariantClear(&value); + store->Release(); + } + + return name; + } + + void record(const char *kind, LPCWSTR id, const char *detail) + { + std::string subject; + + { + std::lock_guard lock(_mutex); + auto it = _names.find(id); + + subject = it != _names.end() && !it->second.empty() ? + it->second : narrow(id); + } + + logf("%s %s: %s", kind, subject.c_str(), detail); + addEvent({ nowMs() - _originMs, kind, subject, detail }); + } + + double _originMs; + IMMDeviceEnumerator *_enumerator; + std::mutex _mutex; + std::map _names; + std::vector _events; +}; + +} // namespace + +std::string runWatch(const WatchOptions& options) +{ + double originMs = nowMs(); + std::wstring instanceId = sarDeviceInstanceId(); + IMMDeviceEnumerator *enumerator = nullptr; + + if (instanceId.empty()) { + logf("No SAR device node found; watching endpoints only"); + } else { + logf("Watching KS interfaces of %s", narrow(instanceId).c_str()); + } + + HRESULT hr = CoCreateInstance(__uuidof(MMDeviceEnumerator), nullptr, + CLSCTX_ALL, __uuidof(IMMDeviceEnumerator), (void **)&enumerator); + + if (FAILED(hr)) { + logf("CoCreateInstance(MMDeviceEnumerator) failed: %s", hresultText(hr).c_str()); + return "{\"error\": \"no device enumerator\"}"; + } + + EndpointWatcher watcher(originMs, enumerator); + + enumerator->RegisterEndpointNotificationCallback(&watcher); + + std::set enabled = enabledInterfaces(instanceId); + + logf("%zu SAR interfaces enabled at start", enabled.size()); + + double deadline = originMs + options.durationSeconds * 1000.0; + double nextProbe = originMs; + double nextCpu = originMs + 1000.0; + ServiceCpu builderCpu(L"AudioEndpointBuilder"); + ServiceCpu audiosrvCpu(L"Audiosrv"); + std::map lastProbe; + long long probes = 0, probeFailures = 0; + + while (nowMs() < deadline) { + if (!options.stopFile.empty() && + GetFileAttributesW(options.stopFile.c_str()) != INVALID_FILE_ATTRIBUTES) { + logf("Stop file found"); + break; + } + + std::set now = enabledInterfaces(instanceId); + + for (const auto& ref : now) { + if (!enabled.count(ref)) { + logf("interface %s: enabled", ref.c_str()); + watcher.addEvent({ nowMs() - originMs, "interface", ref, "enabled" }); + } + } + + for (const auto& ref : enabled) { + if (!now.count(ref)) { + logf("interface %s: disabled", ref.c_str()); + watcher.addEvent({ nowMs() - originMs, "interface", ref, "disabled" }); + } + } + + enabled.swap(now); + + if (nowMs() >= nextCpu) { + double builder = builderCpu.delta(); + double audiosrv = audiosrvCpu.delta(); + + nextCpu += 1000.0; + + if (builder >= 50.0 || audiosrv >= 50.0) { + char detail[96]; + + sprintf_s(detail, "builder %.0f ms, audiosrv %.0f ms", builder, audiosrv); + logf("cpu %s", detail); + watcher.addEvent({ nowMs() - originMs, "cpu", "services", detail }); + } + } + + if (options.probeMs > 0 && nowMs() >= nextProbe) { + nextProbe = nowMs() + options.probeMs; + + for (const auto& pair : enabledInterfacePaths(instanceId)) { + double t0 = nowMs(); + DWORD result = probeFilter(pair.second); + double took = nowMs() - t0; + auto it = lastProbe.find(pair.first); + + probes++; + probeFailures += result != ERROR_SUCCESS; + + if (it == lastProbe.end() || it->second != result || took > 500) { + char detail[96]; + + sprintf_s(detail, "%s (%lu) in %.0f ms", + result == ERROR_SUCCESS ? "opened" : "open failed", + result, took); + logf("probe %s: %s", pair.first.c_str(), detail); + watcher.addEvent({ t0 - originMs, "probe", pair.first, detail }); + } + + lastProbe[pair.first] = result; + } + } + + Sleep((DWORD)options.pollMs); + } + + enumerator->UnregisterEndpointNotificationCallback(&watcher); + enumerator->Release(); + + std::vector items; + + for (const auto& event : watcher.events()) { + JsonObject item; + + item.setDouble("ms", event.ms) + .setString("kind", event.kind) + .setString("subject", event.subject) + .setString("detail", event.detail); + items.push_back(item.str()); + } + + JsonObject result; + + result.setString("command", "watch") + .setBool("passed", true) + .setInt("exitCode", 0) + .setString("sarDevice", narrow(instanceId)) + .setInt("events", (long long)items.size()) + .setInt("probes", probes) + .setInt("probeFailures", probeFailures) + .setRaw("timeline", jsonArray(items)); + return result.str(); +} + +} // namespace SarTest diff --git a/SarTest/watch.h b/SarTest/watch.h new file mode 100644 index 0000000..f659108 --- /dev/null +++ b/SarTest/watch.h @@ -0,0 +1,42 @@ +// SynchronousAudioRouter +// Copyright (C) 2026 Mackenzie Straight +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with SynchronousAudioRouter. If not, see . + +#ifndef _SAR_TEST_WATCH_H +#define _SAR_TEST_WATCH_H + +#include "common.h" + +namespace SarTest { + +// Logs, with timestamps, every change in which of the SAR device's KS +// interfaces are enabled and every endpoint state change Windows reports, +// until the duration passes or the stop file appears. For lining up what the +// driver and the audio endpoint builder did with what clients saw. +struct WatchOptions +{ + double durationSeconds = 60.0; + std::wstring stopFile; + int pollMs = 20; + // How often to try opening every enabled SAR filter by its interface + // path, logging each change in the result; 0 to not probe. + int probeMs = 0; +}; + +// Returns the results JSON. +std::string runWatch(const WatchOptions& options); + +} // namespace SarTest +#endif // _SAR_TEST_WATCH_H diff --git a/tools/test/Invoke-SarTest.ps1 b/tools/test/Invoke-SarTest.ps1 index e944685..613248f 100644 --- a/tools/test/Invoke-SarTest.ps1 +++ b/tools/test/Invoke-SarTest.ps1 @@ -36,7 +36,10 @@ param( [switch]$SkipKillTest, # Any of issues, matrix, race, kill, browser. Installation always runs. [string[]]$Scenarios = @('issues', 'matrix', 'race', 'kill', 'browser'), - [int]$RaceCycles = 10 + [int]$RaceCycles = 10, + # Extra idle time between the race and the kill scenario, on top of + # waiting for the endpoint builder to go idle (diagnostics). + [int]$PostRaceDelaySeconds = 0 ) $ErrorActionPreference = 'Stop' @@ -271,6 +274,35 @@ if ($Scenarios -contains 'browser') { Set-ItemProperty $updatePolicy UpdateDefault 0 -Type DWord } +# Waits until Windows' audio endpoint builder has worked off the endpoint +# changes earlier scenarios caused, and returns the seconds waited. A burst +# of host restarts (the race) leaves it busy for a while, tearing down and +# rebuilding SAR endpoints one at a time; streams opened meanwhile stall in +# Activate/Initialize or fail. Idle: under 100 ms of its CPU per second for +# three seconds in a row. +function Wait-EndpointBuilderIdle { + param([int]$TimeoutSeconds = 120) + + $svc = Get-CimInstance Win32_Service -Filter "Name='AudioEndpointBuilder'" + $proc = if ($svc) { Get-Process -Id $svc.ProcessId -ErrorAction SilentlyContinue } + $started = Get-Date + + if (-not $proc) { return 0 } + + $last = $proc.TotalProcessorTime.TotalMilliseconds + $quiet = 0 + + while (((Get-Date) - $started).TotalSeconds -lt $TimeoutSeconds -and $quiet -lt 3) { + Start-Sleep -Seconds 1 + $proc.Refresh() + $now = $proc.TotalProcessorTime.TotalMilliseconds + if ($now - $last -lt 100) { $quiet++ } else { $quiet = 0 } + $last = $now + } + + return [math]::Round(((Get-Date) - $started).TotalSeconds, 1) +} + # Windows Server images ship with the audio stack disabled. foreach ($service in 'AudioEndpointBuilder', 'Audiosrv') { try { @@ -337,6 +369,20 @@ if ($Scenarios -contains 'matrix') { } } +# Timeline of SAR interface and endpoint state changes across the race, kill +# and recovery scenarios, for lining up with what their clients saw. +$watchProc = $null +if ($Scenarios -contains 'race' -or $Scenarios -contains 'kill') { + $watchStop = Join-Path $ResultsDir 'watch.stop' + $watchJson = Join-Path $ResultsDir 'watch.json' + Remove-Item $watchStop -ErrorAction SilentlyContinue + $watchProc = Start-Process -FilePath $sarTest -NoNewWindow -PassThru ` + -RedirectStandardOutput (Join-Path $ResultsDir 'watch.log') ` + -ArgumentList @('watch', '--duration', 3600, '--stop-file', "`"$watchStop`"", + '--results', "`"$watchJson`"") + $null = $watchProc.Handle +} + if ($Scenarios -contains 'race') { # Start and stop the host over and over while other threads keep opening # streams on its endpoints: the start-up race reported against @@ -347,6 +393,26 @@ if ($Scenarios -contains 'race') { '--openers', 4) + $common) } +if ($Scenarios -contains 'race') { + # Let the endpoint builder catch up with the race before the kill + # scenario, so recovery-after-kill measures recovery from a killed host + # rather than the race's aftermath. How long that takes is the race's + # cost to Windows; a builder still busy after two minutes fails. + $settleTimeout = 120 + $waited = Wait-EndpointBuilderIdle -TimeoutSeconds $settleTimeout + Write-Host "==> settle-after-race : endpoint builder idle after $waited s" + $summary.scenarios += [ordered]@{ + name = 'settle-after-race' + outcome = if ($waited -lt $settleTimeout) { 'passed' } else { 'failed' } + seconds = $waited + } + + if ($PostRaceDelaySeconds -gt 0) { + Write-Host "==> idling another $PostRaceDelaySeconds s" + Start-Sleep -Seconds $PostRaceDelaySeconds + } +} + if (-not $SkipKillTest -and $Scenarios -contains 'kill') { # Kill the ASIO host while WASAPI clients are streaming, then check that a # fresh host can still create endpoints afterwards. @@ -387,6 +453,11 @@ if (-not $SkipKillTest -and $Scenarios -contains 'kill') { @('run', '--endpoints', $count, '--iterations', 1, '--duration', $Duration) + $common) } +if ($watchProc) { + New-Item -ItemType File -Path $watchStop -Force | Out-Null + if (-not $watchProc.WaitForExit(30000)) { try { $watchProc.Kill() } catch { } } +} + if ($Scenarios -contains 'browser') { # With application routing on, the driver points the audio device # enumerator's COM registration at SarAsio.dll for every process of the diff --git a/tools/test/README.md b/tools/test/README.md index 43b445d..de59cb1 100644 --- a/tools/test/README.md +++ b/tools/test/README.md @@ -82,6 +82,23 @@ watched; one that does not return within `--phase-timeout` is reported as `HANG`. The scenario fails if any call hung, the host failed to start or stop, or no stream was ever opened. +After the race, `settle-after-race` waits (up to two minutes) for Windows' +audio endpoint builder to go idle and records how long that took. The +race's restarts queue more endpoint arrivals and removals than the builder +can process as they happen; with 16 pairs it stays busy for about 15 s +afterwards, tearing down and rebuilding SAR endpoints one at a time, and +streams opened meanwhile stall for up to 4 s in Activate (and longer in +Initialize, which the audio service serializes) or get invalidated. Without +the wait, `recovery-after-kill` measured that instead of recovery from a +killed host. + +`SarTest.exe watch` runs from before the race through recovery and logs, +with timestamps, every change in which SAR KS interfaces are enabled, every +endpoint state change Windows reports, and seconds in which the endpoint +builder or audio service used 50 ms of CPU or more (`watch.log`, +`watch.json`). An endpoint that goes `notpresent` while its interface stays +enabled is the endpoint builder rebuilding it. + The `issue-*` scenarios are regression checks for specific GitHub issues. `SarTest.exe control-panel` (#133) opens SAR's control panel on a running host, presses the hardware interface's Configure button and checks that the @@ -120,6 +137,7 @@ SarTest control-panel SarTest no-interface SarTest endpoint-names SarTest meter [--duration S] [--process ] [--min-peak P] +SarTest watch [--duration S] [--stop-file ] [--poll MS] [--probe MS] ``` `install` creates the SAR software device node if needed, installs the