Possible 5.0.1 Shutdown Bug

(FYI - I don't know if this exact version of "slow" shutdown pertained to 5.0).

I upgraded my Windows 10 installation of HW5.0 to 5.0.1, with no known issues nor problems. I stumbled on a delay in shutting down HW. In the simplest case, I cleanly start HW, load a small instrument (I've been using the SP Klavichord for this test.) The PC is fast, ~2 seconds from "Load Organ..." to playable. Play a few notes, then either click on the close button (upper right-hand corner "X" on the main window) or use the File->Exit menu command. HW begins its shutdown, but then hangs with all its windows still painted, but HW goes non-responsive. One CPU core goes to 100% due to HW, but Windows Task Manager shows no paging or I/O on behalf of HW. Seems to average about 30-60 seconds, then it terminates. This delay happens most, but not all of the time. The system as a whole remains fully responsive, only HW seems affected. This behavior occurs with or without a Page File allocated to the OS.

One work around I discovered - if I cold-start another program that opens a window, such as Task Manger or a browser, then HW immediately completes its shutdown as the second program's window paints. But the new program seems to need to be a complete fresh task instance - re-invoking something that stayed resident in the background does not unfreeze HW. When I use the menu File->Exit command, HW's little Progress-bar window paints, but also freezes about 1 second into the shutdown.

My OS is the latest general release Windows 10 Pro (1909), patched up to date, all drivers et al current and so forth.

Cheers, Bob

There have been other HW issues with 1909. Can you try an older version of Win 10 w/o 1909?

Rgds,
Ed

Ed, I may still have an image backup taken one major release back prior to 1909 - if so, I'll give it a go, perhaps this weekend. I've been working with a major SSD/HDD vendor on a bizarre failure of one of their SSDs, and they want me to try the opposite - installing an as-yet not general release Fast-ring version of Windows. Versions bouncing all over the place!

I want to step carefully here, so I don't accidentally blow off anything important whilst mucking with versions - and to not overwhelm daily local and cloud backups with too many radical, but temporary changes . I'll keep you up-to-date.

Oh well, no rest for the wicked...

Cheers, Bob

[mdyde]

Hello Bob,

I'm sure the issue won't actually be due to a bug in Hauptwerk v5.0.1 itself.

Since there is a known performance issue (regression) within Windows itself in recent-ish Windows 10 versions whereby Windows is extremely slow to free locked memory (which Hauptwerk needs to use unless the Windows page file is completely disabled, in order to avoid audio glitches), please first make sure that no page file at all is enabled on any of your drives, as described in step 2 in the Hauptwerk installation instructions (page 24 in the current v5.0.1 version).

Please also make sure that all Windows power-saving functions are completely disabled, as covered in the 'Performance tuning | Other operating system and computer optimizations and diagnostics' section in the Hauptwerk user guide (page 253). Perhaps the computer is putting some device to sleep for some reason (e.g. the SSD/HDD, or a USB-MIDI device).

Assuming those things don't fix it, my guess is that it's actually your audio driver/device or an enabled MIDI driver/device that's being extremely slow to stop. Next time that such a delay happens, wait and allow Hauptwerk to finish exiting. Then re-launch it, and use 'Help | View activity log' to find (by timestamps) what was happening at the time of the delay. When you exit with an organ loaded, Hauptwerk will stop the audio driver, then the MIDI drivers/ports one-by-one, similar to this:

2020-03-06-13-50-44: INF:5122 Stopping audio output device 'RME UFX'. (Pri: ???:63, smallest buffer fill: 1024 frames, largest: 1024 frames.)

2020-03-06-13-50-44: INF:5099 Audio stopped.

2020-03-06-13-50-44: INF:3828 Stopping MIDI.

2020-03-06-13-50-44: INF:3834 Stopping MIDI IN port 'E-MU XMidi1X1 Tab In'.

2020-03-06-13-50-44: INF:3826 MIDI stopped.

If there is a long wait between a device's 'stopping' message and its following 'stopped' message then that indicates that it's that particular device/driver that is causing the delay. (Devices normally stop almost instantaneously.)

Thanks kindly Martin. I've attached the log file entry from my last try after my signature. No Page File, all Power Management copacetic and verified. The two MIDI devices are a directly attached M-Audio 61, and a CMW keyboard attached through a MidiSport Uno. Audio out through ASIO4ALL. In the log, it looks like they all shutdown immediately as expected - in fact, they are started, stopped, and restarted without delay previously in the log, seemingly as part of organ startup. All the delay is the 25 seconds between the MIDI stopped event 3826 and the summary entry event 2509.

Upon upgrade to 5.0.1, I experimented with restoring some page file allocation to allow memory dumps, just wondering if the new HW memory allocation logic might have any impact on the Win10 memory release bug. What I found instead was that the shutdown hang-up rate went from "I don't recall the last time this happened." to about 75%+ - whether or not I had a page file allocated. Pretty much all else about the system is the same. I'm able to turn-around tests rather quickly - load a small instrument, play a chord, shutdown HW. I experimented with several smaller instruments, including St. Anne's - didn't matter.

Regardless, it is hardly "fatal", as I found my trusty work-around - starting another program immediately releases HW. Besides, who really wants to shut down such a marvelous beast?

Cheers, Bob
___
2020-03-06-10-25-35: INF:0402 Hauptwerk is shutting down.

2020-03-06-10-25-35: INF:2507 Stopping audio and MIDI. [Mem. usage stats. MB: Approx. est. of tot. usable phys. mem. remaining: 58451, Approx. est. Hauptwerk sample/obj. mem. (excl. other data): 687 (617 pageable). Approx. pct. phys. mem. used: 1, OS tot. 'available' phys.: 58451, OS commit tot.: 2, OS tot. page file: 0, OS tot. virtual: 65464, OS mem. load pct: 10, OS sys. cache: 1, OS process commit: 814, OS process page faults: 0, OS process work. set: 804, OS process min. work. set: 8735, OS process max. work. set: 63416.]

2020-03-06-10-25-35: INF:5097 Stopping audio. Priorities: plug-in link: --, Win DS: --.

2020-03-06-10-25-35: INF:5122 Stopping audio output device 'ASIO: ASIO4ALL v2'. (Pri: 31[256:15], smallest buffer fill: 256 frames, largest: 256 frames.)

2020-03-06-10-25-35: INF:5099 Audio stopped.

2020-03-06-10-25-35: INF:3828 Stopping MIDI.

2020-03-06-10-25-35: INF:3825 Stopping MIDI IN port 'USB Uno MIDI Interface'. (Driver pri: 24[256:0]. Engine pri: 26[256:2]. Buff: floods: 0, peak usage: 0 pct, total traffic: 0.0 KB. Event perf stats: min ms/avg ms/max ms/total num/num 0-1.9ms/num 2-4.9ms/num 5-9.9ms/num 10-19.9ms/num 20-49.9ms/num >=50ms: event latency: '1.0 / 1.0 / 1.0 / 6 / 6 / 0 / 0 / 0 / 0 / 0', processing time: '0.0 / 0.0 / 0.1 / 6 / 6 / 0 / 0 / 0 / 0 / 0', processing overrun: '0.0 / 0.0 / 0.0 / 5 / 5 / 0 / 0 / 0 / 0 / 0')

2020-03-06-10-25-35: INF:3834 Stopping MIDI IN port 'USB Keystation 61es'.

2020-03-06-10-25-35: INF:3826 MIDI stopped.

2020-03-06-10-26-00: INF:2509 Stopped audio and MIDI. Peak levels since last started: audio: -200.0 dB (>=0 dB indicates clipping), polyphony as pct of limit: 0.0, estimated audio CPU load during first 10 seconds: 6.8 pct, thereafter: 0.0 pct. Ran at real-time priority (Windows only)?: Y. Extra time allowed when audio started (Windows only): 0.0 s. Sample rate: 48000 Hz. Num active stereo reverbs: 1, Max active reverb length: 3.72 s. Expected buffer latency: 256 frames, actual max buffer latency: 256 frames (5.3 ms), max single buffer latency allowed for: 384 frames (8.0 ms).
[Priorities: audio engines: 31[256:15], audio recorders: 31[256:15], mixer convolver FIR preparation/buffer allocator: 24[256:0], convolver engines: --, MIDI player: --, MIDI recorder: 26[256:2], GUI rendering: 24[256:0], default user events: 25[256:1].]
[Event buffer stats: (size in K-events, num floods, peak frac full pct, total traffic in K-events): GUI rendering: (64.0, 0, 0.00, 0.4), high-pri events: (8.0, 0, 0.00, 0.0), default user events: (8.0, 0, 0.00, 0.1).] [Background models:
relay models: (priority: 26[256:2], model perf stats: min ms/avg ms/max ms/total num/num 0-1.9ms/num 2-4.9ms/num 5-9.9ms/num 10-19.9ms/num 20-49.9ms/num >=50ms: processing stats: 0.0 / 0.0 / 0.0 / 2898 / 2898 / 0 / 0 / 0 / 0 / 0, waiting stats: 1.0 / 2.2 / 3.0 / 2898 / 1423 / 1475 / 0 / 0 / 0 / 0, interval stats: 1.0 / 2.2 / 3.0 / 2898 / 1132 / 1766 / 0 / 0 / 0 / 0),
trem model: (priority: 26[256:2], model perf stats: min ms/avg ms/max ms/total num/num 0-1.9ms/num 2-4.9ms/num 5-9.9ms/num 10-19.9ms/num 20-49.9ms/num >=50ms: processing stats: 0.0 / 0.0 / 0.0 / 2898 / 2898 / 0 / 0 / 0 / 0 / 0, waiting stats: 1.0 / 2.2 / 3.0 / 2898 / 1221 / 1677 / 0 / 0 / 0 / 0, interval stats: 1.0 / 2.2 / 3.0 / 2898 / 1156 / 1742 / 0 / 0 / 0 / 0),
wind supply model: (priority: 26[256:2], model perf stats: min ms/avg ms/max ms/total num/num 0-1.9ms/num 2-4.9ms/num 5-9.9ms/num 10-19.9ms/num 20-49.9ms/num >=50ms: processing stats: 0.0 / 0.0 / 0.1 / 2898 / 2898 / 0 / 0 / 0 / 0 / 0, waiting stats: 1.0 / 2.2 / 3.0 / 2898 / 2390 / 508 / 0 / 0 / 0 / 0, interval stats: 1.0 / 2.2 / 3.0 / 2898 / 1175 / 1723 / 0 / 0 / 0 / 0),
pipework: (priority: 26[256:2], model perf stats: min ms/avg ms/max ms/total num/num 0-1.9ms/num 2-4.9ms/num 5-9.9ms/num 10-19.9ms/num 20-49.9ms/num >=50ms: processing stats: 0.0 / 0.0 / 0.0 / 2898 / 2898 / 0 / 0 / 0 / 0 / 0, waiting stats: 1.0 / 2.2 / 3.0 / 2898 / 1346 / 1552 / 0 / 0 / 0 / 0, interval stats: 1.0 / 2.2 / 3.0 / 2898 / 1224 / 1674 / 0 / 0 / 0 / 0),
master: (model perf stats: min ms/avg ms/max ms/total num/num 0-1.9ms/num 2-4.9ms/num 5-9.9ms/num 10-19.9ms/num 20-49.9ms/num >=50ms: processing stats: 0.0 / 0.0 / 0.1 / 2898 / 2898 / 0 / 0 / 0 / 0 / 0, waiting stats: 1.0 / 2.1 / 3.0 / 2898 / 2399 / 499 / 0 / 0 / 0 / 0, interval stats: 1.0 / 2.2 / 3.0 / 2898 / 1107 / 1791 / 0 / 0 / 0 / 0).]
Voice generator background model event stats: total num event blocks: 321, num event queue underflowed blocks: 0 (0.00 pct), mean block length for non-underflowed blocks: 4.0 ms.
Voice generator note-on events stats: total num processed: 3, mean time waited before events: 111 frames (2.3 ms).

2020-03-06-10-26-00: INF:0403 Hauptwerk has finished shutting down.

Martin, one other telling update: while working with a mainstream SSD vendor trying to resolve a mystery that was causing storahci event 129 system startup headaches with their (and only their) SSD, I ran an experiment of loading Fast-Ring Windows pre-release build 19577.1000. Not only did the SSD issue go away, but so did all HW 5.0.1 shutdown delays! I tried about a dozen HW5.0.1 cycles, never a delay. FYI, the SSD problem is not in the critical path of my HW mainstream use - that drive held all my HW post .rar/pre cache files - as it introduced a 10 minute PC startup hangup until the SSD became usable, I'd replaced it with a different vendor's drive, no problems. So there is hope that MS will soon fix its memory management bug. Soon. I hope.

Ed - I won't be able to run your suggested experiment, turns out I no longer have a pre-1909 Windows image at my disposal.

When HW5.0.1 worked fine with the pre-release Windows, I flashed on a vision of a football team (fill in your favorite Rugby or American FB team) all huddled in a circle, arms interlocked, swaying back-and forth while chanting with an ever increasing pace "Haupt-Werk, Haupt-Werk, Haupt-Werk...".

As ever, thanks Martin!

Bob, I sure do agree about Build 19577.1000. Your post encouraged me to get back on the Fast Lane for Windows Updates and try the latest release. I can now unload 85GB of Goerlitz samples in approximately 30 seconds. That's excellent and smaller sample sets unload really fast. Now if Microsoft doesn't accidentally "unfix" this we will all be much happier with Win 10.

I had the exit problem a month or so ago and have just installed the latest Windows updates (V1909 Build 18363.693).

The shutdown problem has gone away in Windows 1909. HW exits almost instantly from a large sample set.

csw900

[mdyde]

Hello Bob,

Does LatencyMon ( https://resplendence.com/latencymon ) report any hardware/driver performance issues on your Windows 1909 installation? I think there must be some kind of hardware/driver issue (perhaps related to the graphics card or SSD/HDD, or conceivably even a bug in Windows itself) that's causing it on your PC, since simply opening one unrelated application certainly shouldn't be able to affect another application in the way that you're seeing.

CSW: In my case, I'm seeing the problem with 1909 Build 18363.693. Unfortunately, I was away from HW for nearly a month until 5.0.1 was released, so my personal memory-cache of previous system behavior was well and thoroughly flushed by the time I noticed this. I had been running with page-file disabled for some time, based on Martin's recommendation for HW5.0 - and at that time, the no page-file workaround had resolved the problem.

Martin: I do believe it to be a subtle windows bug in Windows, perhaps interacting with one or more other anomalies. LatMon has consistently shown this machine to have OK latency. I just ran it now while recreating the shutdown delay a few times in succession. Average Int->Proc was 20us, max was 216us; max ISR was 124us; average DPC around 20us, max 630us. In the weeds, the highest consumers are the TCP/IP stack and DirectX (in this case supporting an NVIDIA 2070S card), which has been pretty consistent Windows behavior across several of my machines for years. I attribute those latency measurements to the brute-force of a fast CPU (Ryzen 3900x), not to Windows. Windows appears to have seriously broken latency control several releases ago, and fast CPUs are finally catching up. This is not a dedicated HW machine, so it is running a full stack, Internet-connected, Norton AV, all the usual Windows background stuff enabled and running, no special latency tuning, only the "no page-file" concession. 99nth percentile idle-time CPU usage is <1%, and I've never heard an audio glitch, and rarely seen the HW CPU-indicator press beyond the first bar. In fact, it is common that CPU and Polyphony light no bars at all, unless I'm pulling a lot of stops and using a lot of reverb. Absolutely flawless! With the polyphony test organ, I had to hit 30,000 pipes to raise CPU over 50%.

My key indicator is that this went away when I was testing Fast-Ring Windows release 19555.1000, working with a tech from Western Digital. The obscure WD problem also went away with 19555! However, other than yesterday's testing, that SSD hasn't been in this PC for 2 months, as the problem rendered the PC intolerable. So there are definitely a series of subtle problems, despite all components being modern, fairly high-end, but no pressing beyond stock parameters e.g. not over-clocked. And I've run extensive off-hour stress tests and diagnostics, with no problems raised when I'm running stock.

Mucking about with my work-around, it appears that it is opening and painting a totally new window that is the salient event. Merely starting processes, or opening new "tabs" within existing windows, or restoring minimized windows, or repainting windows - all seem to have no effect.

One last anecdotal impression (small sample-set!): if HW is up and running for a bit, even as little as 1 minute with minor playing, the chances of hanging seem to decrease noticeably. Most of my recent tests have been quick - start HW, load a small instrument, play 3-5 notes, shutdown.

I wouldn't spend any more time on this on my account - I just wanted to give you the most data I could to improve your understanding of what's up. And I'm very pleased that the new code MS is testing right now seems to solve a number of obscure bugs - hope those changes are intentional and make it into general release. Soon!

Cheers, Bob

[mdyde]

Thanks very much, Bob.

Yes -- I'm sure it isn't due to any bug in Hauptwerk, but it's good to hear that whatever it was/is, Microsoft have fixed it anyway!

I wouldn't spend any more time on this on my account - I just wanted to give you the most data I could to improve your understanding of what's up. And I'm very pleased that the new code MS is testing right now seems to solve a number of obscure bugs - hope those changes are intentional and make it into general release. Soon!
Cheers, Bob

I've also tested the Windows 10 B2004 OS Compilation 19587.1000. It really improved sampleset unload rate, but not to the level of Windows 10 <1709 builds, nor to the any release performance with no memory paging file. On my notebook-based HW system, unload rate rose from 400MB/s (B1909) to 1300MB/s (B2004 Comp 19587.1000), but far below the 4GB/s when memory paging file is off.

[mdyde]

Hello abaymajr,

Thanks for the information. At least Microsoft are improving it again (even if only partially).