ASIO audio glitches on ASUS ROG FLOW X16 - need help with WPA

The timer resolution is intermittently being changed to 15.6ms - take a look at the Timer Resolution graph - you can see that it jumps from 1ms to 15.6ms at the moment the ~13ms glitch ends (presumably around the time of the timer interrupt) How can we determine what requested this change? My audio interface does require a 1ms timer, so this tallies. I know this because I had set the default interval to 15.6ms (by running powercfg /energy - I didn't know it would make a permanent change!). I couldn't figure out how to put it back to 1ms, so I reasoned that my audio interface probably requires 1ms, and wondered whether if I installed the driver that it would put the system default to 1ms - indeed it did. I don't think the default matters much though - it appears that anything that needs a particular resolution can simply make the change, at least for the duration if requires it.

Hello Greg,

The timer resolution is a major area of investigation for your issue but it is a complex topic (see the section "Timer processing" in the Windows Internals book).

I don't think that the event you are referring to is an explicit setting of the resolution to 15.625 ms but rather the end of a period when a different resolution had been set (probably matching a timeEndPeriod call) and the resolution reverts to its default value.

Gary

With respect, I completely disagree with your assessment - it is very obvious that the timer resolution was set to 15.6ms, for a single timer tick - that's why all the timer related events (refer kernel activity) which normally occur every 1ms, stop for roughly 15.6ms. That's why there's a glitch in the audio - the USB is stalled for a whopping 15.6ms. Remember, I'm using a buffer size of 128 samples @ 44.1kHz - that's just 2.9ms. In any case - GOOD NEWS - I've found the culprit - it's optional AMD Radeon related software which I can simply disable. (shows up as "AMD Software" in Task Manager). Updating it doesn't fix it, so I'll report this to ASUS and/or AMD, just for good measure, even though it's not important to me for audio. I'll refer them to this discussion. Thanks again for your time. 😀

Active Gary, if you're simply saying that whilst the timer resolution appears to have been changed, it may not have been set to 15.6ms as the graph suggests, I'll go along with that. It does seem very clear to me though that it was changed, and that change causes the problem - agreed? The evidence seems overwhelming.

I might be wrong about Radeon - I need to do more testing. (I do think stopping that process has improved things, though, if it doesn't completely solve it)
In any case, here's another trace, and the timer resolution trace looks VERY different to the previous one. Why is Chrome now requesting an 8ms clock? And why does it seem to be saying that the "actual" system timer is a constant 15.6ms now? The command line Clockres utility says the "current" resolution is 1ms - not 15.6. This trace was recorded using battery power - maybe that has something to do with it.
I owe you an apology Gary - I have no idea what's going on with the timer. Sorry. 🤣

https://drive.google.com/file/d/1_tOMtke9FEhhjDUyT3nMx1iOw1Lvf18q/view?usp=sharing
Refer ~48.1s for the familiar ~14ms interruption of timer ticks.

Should I crosspost in the systems internals forum?

Hello Greg,

dynamic tick, coalescable timers, multimedia timers, waitable timers (plus/minus flag CREATE_WAITABLE_TIMER_HIGH_RESOLUTION), serialized timer expiration, etc. all combine to make analysis of timer behaviour complicated.

I am currently working on finding the best set of trace providers, keywords, levels and stack traces that give me the best insight into what is happening in any particular case.

Cross posting to relevant forums can do no harm; it is my impression that the "Sysinternals" forum is for users of the tools rather than developers - its summary says "Advanced system utilities to manage, troubleshoot, and diagnose Windows and Linux systems and applications."

Gary

Thanks. I'll hold off cross posting for now. I'll try to reproduce on another machine in the meantime. Just in case it's relevant, the "Perfinfo" category looks busier on the problematic machine in terms of timer related calls, compared to the well behaving machine.

Hello Greg,

This is the type of thing that I am looking at: I am using CreateWaitableTimerEx to create a timer with flag CREATE_WAITABLE_TIMER_HIGH_RESOLUTION. I send a UDP packet when the timer runs to make that time easily findable in the trace. Here is one example where a timer with interval 5 ms first runs after 6.2 ms.

My timer with 5 ms period (50,000 100 ns ticks) triggers (opcode ExpireKTimer2) and thread 0x20AC (decimal 8364) is made ready; 0.5 ms later the thread begins to run on processor 2 (the previous thread on that processor was 0 (i.e. idle)). So 0.5 ms of the 1.2 ms delay was due to thread scheduling - possible the power/idle state of processor 2; I will need to add some more trace providers to track that behaviour.

Gary

I've made a silly mistake. Setting the power profile settings "Processor Idle Demote Threshold" & "Processor Idle Promote Threshold" both to 100% makes a big improvement, but over the last few days, I've been testing with these on the default values. Sorry about that.
With these set to 100%, I think it's still failing in the same manner, but less often - about once very 30 to 60 minutes. I've uploaded another trace. This trace was taken using the aforementioned ASIO driver test utility, and WPR was stopped automatically with a Powershell Script that did the same kind of thing as that web page - it repeatedly looped until it detected a 10ms dead period, and then spawned a shell to stop the WPR. The number of times the ASIO utility detected a callback error of 100% was 1, so I'm assuming the script caught the right moment in time.
In order to restrict the buffer size of WPR, I started it with a command and a profile file - it appears that my profile isn't yet as comprehensive as the settings I've been using with the GUI - I'll work on that. Is there a way to simply limit the buffer size that the GUI version uses?
WPR trace - refer time 3515.57s: https://drive.google.com/file/d/1SNYjNNWGWKO9LGDg-A4FfdpXRAowc391/view?usp=sharing
PowerShell script (courtesy Grok): https://drive.google.com/file/d/1t3Vyxf9-a04bybxUk-NV4sGjMOThpr4A/view?usp=sharing

Pete Brown @ Microsoft is helping me over on Gearspace - he's suggested that I try a different way to set my power profile (Settings > System > Power > Power Mode > "Best Performance" - I'll try that next.

Hello Greg,

Your custom profile seems to be missing the "IdleStates" events - these now seem key to understanding the unexpected pauses (this is my current focus).

The only way to set the buffer size that I know of is via the WPRP XML; the custom WPRP can be started via either the command line or the GUI. Using "Memory" rather than "File" "Logging mode" should limit the size of the resulting trace file to the size of the buffered data (or less, if compression is performed).

Gary

Gary - that aforementioned setting has fixed the problem - the test has run for 10+ hours. 😎
Again: Settings > System > Power & Battery > Power Mode > select "Best Performance"
I suggest Microsoft consider merging the "old" and "new" methods of setting the power profile. I was very familiar with the old method, but completely unaware of the new method.

Hello Greg,

Good to hear. It has been interesting to delve into this topic.

A detailed view of a section (around the 48.1 s mark) of your second trace looks like this:

The column marked in green is the processor number; at the bottom of the green section, most processors are in the C3 (Sleep) state - just 7 and 13 (the clock owner) are still running.

In the yellow section, processor 13 enters the sleep state (leaving only processor 7 running) and expects to be woken in 14986 ticks (14.986 ms).

After 13.8 ms, the processors start waking and the next clock tick occurs.

Gary

Excellent! Thanks Gary.
Just FYI, I've concluded that the ASUS utility app "Armoury Crate" is broken, and I have reported this to ASUS.
The way forward for me at the moment seems to be to use a vanilla install of Windows, and to avoid installing A.C at all costs. (even removing it doesn't undo the damage)
I'm trying to find a utility for querying the configuration of the running processor, regarding c-states etc - if anyone knows of something that will work with the mobile AMD processors please advise. (the main one from AMD doesn't support mobile)

Hello Greg,

More insight into the power configuration is my goal too.

There are "hidden" power settings. You could try the following:

• Issue the command "powercfg /list" to get a list of power scheme GUIDs
• Issue the command "powercfg /qh <scheme_guid> 54533251-82be-4824-96c1-47b60b740d00"; 54533251-82be-4824-96c1-47b60b740d00 is the value of GUID_PROCESSOR_SETTINGS_SUBGROUP. "/qh" is undocumented and possibly means "query hidden".
• Perhaps save the output to files and compare schemes. For idle state management settings IDLESCALING, IDLEPROMOTE and IDLEDEMOTE seem to be particularly relevant.

Please let us/me know if you find anything interesting when comparing working/non-working settings that you find for your audio problem.

Gary

Will do. Just a small correction to my previous reply - the root cause may well be the BIOS. I say this because there's an open source substitute for Armoury Crate called "G-Helper", and it's notes say something about the profiles being baked into the BIOS. Sure enough, as soon as I open G-Helper, I can see the ASIO timing get worse, suggesting CPU throttling, despite the fact I've selected it's "Turbo" profile. This happens with Armoury Crate as well. I've checked my BIOS - it's up to date.

Gary,
I need help configuring WPR to run with a small memory buffer. I've created a profile by exporting cpu + power, and I've then tried reducing the system & event buffers, maintaining the same relative proportion. It appears that if I let the capture run for long enough for a wrap-around, it's overwriting old events in a way I don't understand. For example, looking at the absolute time of the events, it appears that categories such as kernel-processor-power &kernel-power don't have any data before the recording was stopped, but do have events AFTER it was stopped. Why do I have anything after it was stopped at all? I don't see a "trace rundown" in this situation either. Is the trace rundown process somehow causing a problem? If so, is there a way to abruptly stop the recording, without the rundown? I only care about events leading up to the STOP command.

Hello Greg,

WPR typically starts two ETW trace sessions, as can be seen with the "logman query -ets" command:

Data Collector Set                        Type                          Status
-------------------------------------------------------------------------------
Circular Kernel Context Logger            Trace                         Running
Diagtrack-Listener                        Trace                         Running
[...]
WPR_initiated_WprApp_WPR System Collector Trace                         Running
WPR_initiated_WprApp_ETW                  Trace                         Running
WinDiag-Realtime-Session                  Trace                         Running

These two files are then merged when WPR is stopped. If you look at the Header event of the resulting trace then the SessionName property is "Relogger" (the files are merged by "relogging") and the LogFileName property is "[multiple files]".

This behaviour, combined with contributions from any rundown and state capture providers could explain what you are seeing.

If you are willing to share your .wprp file and perhaps an example .etl file exhibiting the characteristics that you mention, I can check if the behaviour is expected and perhaps suggest changes to the profile.

Gary

Thanks again. Firstly, the reason I'm still capturing traces is that the aforementioned setting does NOT actually fix the problem. Yes, the test ran for a long time on that particular occasion, but unfortunately, the same problem is still occurring sometimes.
Anyway, I've attached a new WPA screen grab for your perusal, along with the profile file I'm using, and which I'd like to be able to run with a much smaller circular buffer, to make it easier to share ETL files. This profile was created with the following command:
wpr -exportprofile cpu+power cpu_power.wprp
Referring to the screen grab, the test ran for a whopping 5.4 hours before what appears to be the same kind of idling event occurred. It's not apparent from the image, but upon closer inspection of the CPU Idle States graph, CPU 8 appears to be the only core at Idle state 0 (fully active?) during the idle period. For this test, I forced both my Powershell script and the ASIO driver test utility to use CPU 8. (I thought it would make sense for both to be on the same core, and I chose #8 at random)
Regardless of what kind of power plan is active, does it actually make sense to EVER allow CPU 0 to idle for this long (~14ms), given that it's the "main" core, servicing most of the interrupts etc?
Is Idle state 1 actually a true "idle" though? wpa_screen_grab.png
Profile file: cpu_power_wprp.txt

Hello Greg,

Here is some immediate feedback - I might be able to follow-up with some more information/ideas.

I think that idle state 1 (which I interpret to mean C1) just means that the processor has executed the HLT instruction - the processor is "idle" (waiting for an interrupt) but not otherwise in a reduced power state.

Under the menu point Trace -> System Configuration, tab Trace Statistics, one can see how much space each trace provider is using. I just made a very short trace using the CPU + Power profile and this is what that tab shows:

The vast majority of the space is used by information that I consider totally irrelevant for your purposes (DotNET information, only used (as far as I known) in this case to give more meaningful stack traces (IL method names rather than JIT code addresses)).

File operations also seem irrelevant and the ImageId events are only needed for detailed stack traces (routine names rather than just "module" information).

Some large items in the trace file are "genuine" events (created while the trace is still running), such as the DotNET events; some other events (e.g. the ImageId events) are "fabricated" by WPR after the trace has stopped.

If you want to trace for hours then I would carefully consider what needs to be included in the resulting trace file; I would also dispense with most of the "CaptureState Providers on Save" elements since, in the circular capture mode (Memory vs. File), these can cause too much history to be ejected from the buffer(s) when the trace is stopped.

Gary

Hello Greg,

It might be useful to look at: https://stackoverflow.com/questions/48420309/disabling-cpu-idle-c-states-from-kernel-mode-driver

The question is old, but there is a recent (May) response which seems relevant and mentions, in passing, DAWs.

Gary

Thanks. Haven't fully digested it yet, BUT, note that I have tried setting "Processor idle disable" to "Disable idle". It immediately increases the temperature of the cpu, and actually doesn't stop this condition from occurring.
IMPORTANT: This condition (~14ms "idle" time) actually occurs more often if I simply use the system normally, with the network enabled. (open & close apps, browsing, etc etc)
Should I log a support call with Microsoft?
I don't think I've been able to reproduce this idle event thing on the Dell XPS 15 9560 yet, but I'll try a bit more.
Note that Pete Brown@Microsoft asked (on Gearspace) whether I was monitoring temperature, and I replied that I was not. My Powershell script's tight loop was causing the processor to get hot (90C) - I've now improved the script. (and the problem persists)
EDIT: I'll try that new setting (which I know you mentioned earlier):
Processor idle threshold scaling -> Disable scaling
EDIT 2: Unfortunately this setting is already set to "Disable scaling" (sigh!)

Problem reproduced on Windows 10 (on the same hardware)
(I'm very impressed at how well Windows 10 is working overall though, on this relatively modern machine - I expected it to be very difficult to get running, but it was easy)

Hello Greg,

I just noticed another "provider" that could be useful for detailed traces: Microsoft.Windows.Kernel.Timer (notice the dots rather than dashes in the name). This is a TLG (TraceLogging) provider; it can be added to a .wprp profile by preceding its name with an asterisk:

    <EventProvider Id="Timer" Name="*Microsoft.Windows.Kernel.Timer" NonPagedMemory="true" Stack="false" />

It is a "high volume" provider (generates lots of events):

Gary

Thanks. Do you know of a way to trim down an ETL file, to retain only a certain time range?

Hello Greg,

APIs capable of being used to provide this functionality exist (https://learn.microsoft.com/en-us/windows/win32/api/relogger/nn-relogger-itracerelogger) but I am not aware of any publicly available tools that provide this feature.

Gary

Gary,
I added that timer category that you suggested, but I don't see it in the traces. I've attached my profile. wpr_wprp.txt

Hello Greg,

I used your profile to create a trace and the Microsoft.Windows.Kernel.Timer events were present:

Gary

Thanks. When I use logman to query the providers, it doesn't appear - should it?

Hello Greg,

Do you mean "logman query -ets <sessionname>"? It probably does appear in that output, but with a GUID instead of a name:

Provider:
Name:                 {F2D06F08-592D-508C-C3AA-76F396FE18BD}
Provider Guid:        {F2D06F08-592D-508C-C3AA-76F396FE18BD}
Level:                255
KeywordsAll:          0x0
KeywordsAny:          0xffffffffffffffff
Properties:           64
Filter Type:          0

It is a TraceLogging provider rather than a manifested (Crimson) provider, so its definition is not registered and logman can not perform a GUID to name translation.

The reason for the asterisk in front of the name in the profile is that the name cannot be looked up but, in this case, can be calculated by performing a hash calculation on the name (so name to GUID is possible but the reverse process is not possible).

Gary

Here's the output of logman query -ets. Which "session" should I query?

Data Collector Set                      Type                          Status
-------------------------------------------------------------------------------
Circular Kernel Context Logger          Trace                         Running 
Eventlog-Security                       Trace                         Running 
CimFSUnionFS-Filter                     Trace                         Running 
DiagLog                                 Trace                         Running 
Diagtrack-Listener                      Trace                         Running 
EventLog-Application                    Trace                         Running 
EventLog-System                         Trace                         Running 
FaceCredProv                            Trace                         Running 
FilterMgr-Logger                        Trace                         Running 
LwtNetLog                               Trace                         Running 
Microsoft-Windows-Rdp-Graphics-RdpIdd-Trace Trace                         Running 
NetCore                                 Trace                         Running 
NtfsLog                                 Trace                         Running 
RadioMgr                                Trace                         Running 
ScreenOnPowerStudyTraceSession          Trace                         Running 
ReFSLog                                 Trace                         Running 
UBPM                                    Trace                         Running 
WdiContextLog                           Trace                         Running 
WiFiSession                             Trace                         Running 
WPR_initiated_DiagTrackMiniLogger_WPR System Collector Trace                         Running 
WPR_initiated_DiagTrackMiniLogger_OneTrace_User_Logger_20250811_1_EC_0 Trace                         Running 
8696EAC4-1288-4288-A4EE-49EE431B0AD9    Trace                         Running 
SleepStudyTraceSession                  Trace                         Running 
CldFltLog                               Trace                         Running 
ASUS_System_Control_Interface_TraceSession Trace                         Running 
NVIDIA-NVTOPPS-NOCAT                    Trace                         Running 
NVIDIA-NVTOPPS-FILTER                   Trace                         Running 
MpWppCoreTracing-20250808-104119-00000003-100000000 Trace                         Running 
MpWppTracing-20250808-004122-00000003-fffffffeffffffff Trace                         Running 
1DSListener                             Trace                         Running 
WPR_initiated_WprApp_WPR System Collector Trace                         Running 
WPR_initiated_WprApp_WPR Event Collector Trace                         Running 
UpdateSessionOrchestration              Trace                         Running 
MoUxCoreWorker                          Trace                         Running 
Microsoft.Windows.Remediation           Trace                         Running 
SHS-08082025-100058-7-1ff               Trace                         Running 
WinDiag-Realtime-Session                Trace                         Running 

The command completed successfully.

Ah - yes - I see it in the WPR_initiated_WprApp_WPR Event Collector!
So why aren't I seeing that event category? I'm looking at exactly the same screen as you - the Trace Statistics.

Hello Greg,

You have mentioned both Windows 10 and Windows 11 in this thread; are you trying to capture these events on the Windows 11 system?

I don't know with which release of Windows these events were introduced; the "ver" command on my PC shows "Microsoft Windows [Version 10.0.26100.4770]" (Windows 11 24H2).

Gary

Windows 11 Home - currently running the installation that was installed when shipped, updated recently. Will supply exact version soon.

Hello Greg,

I checked the Windows kernel version used when you created browser_01.etl and that seems to support these events.

Gary

Microsoft Windows [Version 10.0.26100.4652]

Hello Greg,

A test for the presence/absence of the events would be to execute the command:

logman start gary -ets -p {F2D06F08-592D-508C-C3AA-76F396FE18BD} -o timer.etl & logman stop gary -ets

The "&" joins the two commands (start and stop); this keeps the duration of the trace short. On my system, a 2.5 MB trace file (timer.etl) was created (a lot of events are generated).

Gary

I fiddled with the buffer sizes, and now it's working. (but I know my original settings worked for you. shrugs) Thanks for your patience.
Here's a new trace - about 90MB compressed: https://drive.google.com/file/d/1rU-JsxBmel71D8XepTjPOJvdLBQMf6hX/view?usp=sharing

This was created by simply opening & closing apps. I don't expect to be able to do this kind of thing when I get back to audio, but it's an easier way to create these strange idle events, that's all. The idle event is right near the end of the trace.

(deleted)

Hello Greg,

Here is a brief extract from the trace at the time of the 14 ms delay between clock interrupts:

There is quite a bit of analysis and inference work to do to determine if the reason for the length of delay can be understood.

Gary

Thanks again. FYI, that last trace was done on battery power, and the power profile wasn't set correctly. (although Pete@Microsoft said that with the "new" method of setting the performance in the System settings, the control panel settings have no effect. I want to revisit that though - I'm not sure this is the case)
Just for good measure, here's another one on AC power, with the power plan settings set correctly: (40MB) https://drive.google.com/file/d/1mk_kO4d9jKJzumYJUAzFRT0PH_5PIJ0H/view?usp=sharing

I've made a small improvement to the Powershell script: it now elevates itself to "High" priority, and only stops the WPR for detected idle periods of 13-19ms inclusive. This eliminates many false triggers. Refer attached.
I'm going to make an effort to either get others to reproduce the issue, or get hold of another machine myself etc.
catch_idle_ps1.txt

Hello Greg,

Looking at the "on battery" trace:

The events indicate that processor 9 (the clock owner) is planning to enter the C2 (clock stop) state for 0.4545 ms and that other threads are active on other processors (processor 12 can be seen in the trace extract).

Rather than being in a low power mode for just 0.45 ms, processor 9 is in a low power state for 13.6 ms; when it resumes activity, it notices that some timers are badly overdue.

There are no trace events during the 13.6 ms pause of processor 9 although threads are active on other processors (I did not check the state of all 16 processors); statistically, I would expect to see some events (e.g. CSwitch) for the active processors.

It appears to me that the whole CPU has "paused" and it looks as though Windows did not intend/instigate this behaviour.

I will now look at your newest trace and perform some tests/tracing on my HP PC.

Gary

Looks like great progress - thankyou. Just FYI, my new PowerShell script has triggered just once so far on the aforementioned XPS 15, but I can't see that same 14ms idle event in the trace. (so it appears to me, as a layman, that the reason for the trigger was simply that the system was busy doing other tasks)

Hello Greg,

Here is an extract from the "on AC power" trace:

Essentially, the same as the on battery trace. The clock owner enters the C2 state, expecting to be idle for 0.8 ms. In this example, events from other processors are logged for a few microseconds after that before a 13 ms period of no activity begins. When the clock owner resumes, it notices that there are badly delayed timer expirations to process.

On my PC, I can detect jitter in CREATE_WAITABLE_TIMER_HIGH_RESOLUTION timer expirations, but it does not match the pattern of "complete" inactivity; I believe that the resolution of these CREATE_WAITABLE_TIMER_HIGH_RESOLUTION timer expirations is reduced when the process is running in the background and that is what I am probably observing in my tests (I am doing other things on the PC while the test runs).

Gary

Thanks again. What's the next step?

Hello Greg,

On my system, the timer expiration seems to occur punctually and reliably - all of my longer "waits" were due to a delay between the ReadyThread event (make the thread ready to run) and the CSwitch event (start executing the thread on a processor); playing with thread priorities would probably improve the results.

I am tending to the belief that the problem is the hardware and not the operating system - testing on many different PCs would help to confirm or refute this belief.

If the problem is outside the operating system (Windows), then I don't have any suggestions about how to improve the situation.

Gary

Did you write a program to test for jitter on the scheduled high resolution waits? If so, would you be able to make it available?

Hello Greg,

It is just a play thing - the UDP sends are present to make the activation of the callback routine easily findable in the trace data (I use the Microsoft-Windows-TCPIP provider with the keyword ut:SendPath to capture that event).

Gary

timer.cs.txt

Thanks. I'm puzzled about something - earlier on, you said this: "In the yellow section, processor 13 enters the sleep state (leaving only processor 7 running) and expects to be woken in 14986 ticks (14.986 ms).

After 13.8 ms, the processors start waking and the next clock tick occurs.". On that occasion, the long idle appeared to be intentional, yet in the most recent traces, you think that they are not intentional. Please clarify. (sorry for the lack of formatting - I'm writing this on my phone, and the enter/new-line key doesn't create a new line)

Hello Greg,

Sorry, I made a mistake there. 14986 ticks is correct but each tick is 100 ns - I should have moved the decimal point 4 places to the left to convert the value to milliseconds. It should be 1.4986 ms.

Gary

Gary,
You mentioned that "the clock owner enters the C2 state". Is that equivalent to an idle state of "2"? The highest I see in the AC trace is 1, not 2.

Hello Greg,

The values are not documented, but I am fairly sure the interpretation is:

0 = C1 (Halted), 1 = C2 (Stop Clock), 2 = C3 (Sleep)

The IdleStateExit event marks the return to the execution state.

Gary

Hello Greg,

What interpretation would you place on the sequence of events "IdleStateEnter 0" and "IdleStateExit 0"? For a particular processor, no other events appear between these two events. It would be difficult to make sense of the sequence of trace events if state "0" meant "active" (busy computing).

"Halted", in this context, just means "currently executing the HLT instruction".

Gary

As long as you're happy that your interpretation tallies with the CPU Idle States graph, which seems to only show states 0 & 1 (on AC power), and 0 - 3 (on battery) FYI I've moved to a Dell XPS 17 9720 as my main machine (which is working properly) - the ASUS will be dedicated to diagnosing this problem. Still trying to find a way to test on another Ryzen 7 6800HS based machine.

Hello Greg,

One can arrange for WPA to show idle state events like this:

One can then use the exact entry and exit times to find the events that WPA used.

For C1, the entry and exit events are IdleStateEnter state 0 and IdleStateExit state 0.

For Active, the entry and exit events are IdleStateExit state <n> and IdleStateEnter state <n>.

For C3, the entry and exit events are IdleStateEnter state 2 and IdleStateExit state 2:

Gary

Thanks. Just btw, did you notice the shorter idle period of 2 to 3ms, at time 28.6181s?

Hello Greg,

I had not noticed it, but it seems to be the same type of behaviour - the whole system pausing (as evidenced by no events of any type) for a prolonged period (2 ms, in this case) even though there is evidence of active computation on some/many processors; also no indication that Windows is responsible for the pause even though the trace is logging probably all of the event sources that might be relevant.

Again, it points to a foible of the hardware rather than Windows.

Gary

Gary,
Just running your program - looks like it's failing in the same manner as my Powershell script. Two runs produced the following, exiting the program each time, indicating a "severe" idle detection:

12334 174464
3191 142944

I was simply opening & closing apps. Note that running without a page file does not change the behaviour. (just a random thing I decided to try)

Still haven't had any volunteers to test on another machine with the same processor. I attempted to buy another example on Ebay (purely out of sheer determination) but lost the bid. I'll keep at it.

Greg

Hello Greg,

As I mentioned, on my system I investigated the long delays and found in all cases (about 5 that I examined in detail) that the timer fired and the thread was readied "on time"; it was the wait for the thread to be scheduled on a processor that accounted for the delay.

Setting various scheduling properties (e.g. priority, foreground, etc.) might improve the behaviour. Since this behaviour was different from that on your system (badly delayed firing of the timer), I did not experiment with those scheduling properties.

Gary

Gary,
I'd like to develop a more robust program, that we could be 100% sure detects ONLY incidences of the system ceasing processing interrupts for an excessive time. Would it be possible to write a program that hooks in more directly to the system timer interrupts, measuring the time duration between these interrupts? Could you give me an overall approach? The reason I want this kind of program is that I suspect I'll have to leave my machine with ASUS soon, and I want to devise the simplest possible test, ideally not requiring the WPR.
I'm also talking to AMD, but I suspect they'll probably end up asking me to take the machine to ASUS. (which is quite reasonable, IMHO)

Hello Greg,

Try this version of timer.cs - I think that it only differs from the previous version by the use of the https://learn.microsoft.com/en-us/windows/win32/api/avrt/nf-avrt-avsetmmthreadcharacteristicsw routine with the task name "Pro Audio".

The measured difference from desired interval rarely exceeds one millisecond.

WPR delivers by far the most accurate measurement of timer expiration and scheduling of the corresponding actions.

Writing kernel-mode code (e.g. a (pseudo) device driver) would get a little nearer to the hardware, but I don't think that even that would offer any better and "clean" (based on documented APIs rather than hacking techniques) way of tapping into the timing system.

Gary

timer.cs.txt

Thanks Gary (haven't tried it yet)
Simply raising the priority to Real Time, in the existing program (same for the Powershell script) seems to help.

A.I has suggested that System Management Interrupts might be a factor, but it appears that the SMI count on AMD processors is not as readily accessible as it is for Intel - any ideas?

Hello Greg,

A.I. may well be correct, but I don't know (not even a whiff of an idea) how to get any insight into that behaviour.

Gary

Problem reproduced on a second example of an ASUS machine with the same processor - it's an ASUS Zephyrus G15 GA503RM, also with the Ryzen 7 6800HS.

The "in depth latency tests" utility in the Pro version of LatencyMon does detect the pause. I believe this utility does something very similar to my script (and your program, Gary). This is great progress, because I can now simply tell ASUS to run this industry standard utility.

Hello Greg,

Your energy in pursuing this problem is impressive. I have seldom succeeded in getting any major company to accept that a problem exists and ultimately getting it fixed (perhaps once or twice with Microsoft software problems, given the backing of my employer's support contract). Even then, the timescales until an improved version was widely available were very long. This problem may be "firmware" (or something else less easily modified than "software") related.

Gary

Thanks Gary, and thanks for all your help and patience - I'm very fortunate to have someone with your expertise. ¶ Re ASUS, to my pleasant surprise, they've agreed to do some investigation without me having to send in a machine, given that I've reproduced it on two examples. This is good progress. ¶ I mentioned System Management Interrupts - my eyes lit up when I saw SMI's mentioned in this other "In Depth" mode of LatencyMon! What it seems to do (more or less) is spin in a tight loop, at very high execution priorities (interrupt level), with the priority level being able to be selected by the user. It detects the 13ms pause even when the ONLY possible interrupt that could interrupt the loop is an SMI. This means that the pause is either caused by an SMI, or some other unexplained reason. (if I'm not mistaken)

Just confirming that the apparent CPU stall does appear to be due to System Management Interrupts - I can now monitor the SMI count, and it increases when the stall occurs.

This is probably related:
https://github.com/Zephkek/Asus-ROG-Aml-Deep-Dive

I've started a discussion in that repo: https://github.com/Zephkek/Asus-ROG-Aml-Deep-Dive/discussions/64

Hello Greg,

That is a nice piece of work from Zephkek (Mohamed Maatallah), but I am not convinced that it is related to your problem. The ACPI interrupts and DPCs are visible to and traceable by the operating system whereas the problematic behaviour of your system is just manifested as "delays without apparent cause".

The description of "Tight Loop High IRQ Level" mode says:

This test allows you to measure the duration of System Management Interrupts (SMIs) as the execution of this test can only get interrupted by SMIs, CPU stall or possible CPU problems

SMIs are one possible explanation, but communication problems arising from the chiplet architecture of the AMD processor might play a role too (power management being located in a component separate from the CPU cores).

Gary

Thanks Gary, and agreed/understood, for the most part. I think we can be confident though that the CPU is executing BIOS code at the time of the glitch, due to the fact SMIs are occurring. If SMIs were NOT occurring, that would indicate a strange hardware pause.

(I'm assuming you saw my reply where I mentioned the SMI count increasing at the time of the CPU stall? I made two replies in quick succession)

Hello Greg,

I saw both posts and was reluctant to assign too much certainty to the "SMI count" data - these values might just be inferences drawn from "loops" executed per time interval. Running in a tight loop might make the processor hot and hardware might modulate the clock speed to reduce the temperature.

The traces that we made seemed to show that processors were slow to return from low power C-states. It is possible that the processors were executing System Management Mode / BIOS code when "glitches" occurred but it also seems possible that they were doing nothing.

When Intel processors want to enter a low power C-state, they seem to use the MONITOR/MWAIT instructions:

 # Call Site
00 intelppm!MWaitIdle (executing: mwait rax,rcx)
01 intelppm!AcpiCStateIdleExecute
02 nt!PpmIdleExecuteTransition
03 nt!PoIdle
04 nt!KiIdleLoop

When AMD processors with the "chiplet" architecture want to enter a low power C-state, they probably communicate with another chiplet:

 # Call Site
00 amdppm!ReadIoMemRaw (executing: in al,dx)
01 amdppm!ReadGenAddr
02 amdppm!C2Idle
03 amdppm!AcpiCStateIdleExecute
04 nt!PpmIdleExecuteTransition
05 nt!PoIdle
06 nt!KiIdleLoop

I don't know enough about these low-level topics, so I would just caution against focussing on one hypothesis (e.g. SMI interrupts) in the absence of persuasive evidence.

Gary

Update your drivers

Thanks again Gary. Whatever the cause of the SMIs, it's nice to have this new supporting evidence that they are occurring. I've fed this info to AMD, despite the fact they insist I go through ASUS - I pleaded with them to put pressure on ASUS to address the issue. (they have been extremely unhelpful to date, but I haven't given up all hope yet)

Jared: drivers etc have been updated to the nth degree.

Please refer to the attached WPA screen, which shows ACPI activity just before the 13ms stall.

Hello Greg,

The choice of "providers" is not what I would choose: the Antimalware, RPC and Search providers don't seem relevant and some useful "Power" events (e.g. Keywords "Power" and "IdleStates") don't seem to be present.

The ACPI events with ID 7 normally come in start/stop pairs - the graph seems to suggest that ACPI activity occurred before the 13ms window (where no events occur) rather than spanning the window.

Gary

Gary: you are 100% correct, there are two start/stop pairs, and the event name for both is: _SB.TPM._DSM This is of course related to the Trusted Computing Platform device. I can reproduce the 13ms stall by querying the TPM in Powershell with the command Get-TPM
Recall that I have been simply launching applications to generate the stalls for a long time. I have to admit that the kinds of apps that cause the problem are "heavy" apps - MS Edge, Copilot, Outlook, Microsoft Store etc. A.I reckons these apps could be expected to query the TPM sometimes. It's also suggesting I try plugging a physical TPM device onto the motherboard. (the vendor id of the existing device is "AMD", which apparently means it's integrated - not discrete)
EDIT: Unfortunately there's no TPM header on my motherboard.

I should now do a regression test - use the system for real time audio in a normal manner, and verify that the (highly intermittent) stalls have the same signature.

Re the extraneous stuff in WPR - yep - sorry - it was just a quick & dirty run of the WPR using the GUI, selecting the Power profile.
EDIT: Well known problem, and shame on ASUS for not informing me: https://www.reddit.com/r/ASUSROG/comments/vubni9/intermittent_system_stutter_experienced_with_ftpm/

Hello Greg,

I had checked the "default" profiles "Power" and "Audio" and did not think them likely candidates; "quick & dirty" is fine though :-)

You could try taking the "Power" profile as a starting point and then adding some additional TPM related providers:

<EventProvider Id="TPM-WMI" Name="Microsoft-Windows-TPM-WMI" NonPagedMemory="true" Stack="true"/>
<EventProvider Id="TPM" Name="TPM" NonPagedMemory="true" Stack="true"/>
<EventProvider Id="TPM-WPP" Name="3a8d6942-b034-48e2-b314-f69c2b4655a3" NonPagedMemory="true" Stack="true">
  <Keywords>
    <Keyword Value="0xFFFFFFFF" />
  </Keywords>
</EventProvider>

This might give some information about why the TPM is being used.

Gary

(deleted by me)