Psychic Perf Analysis, or "RegFlushKey actually DOES flush the registry key"

One of Raymond's more endearing features is what he calls "Psychic Debugging", it even made his wikipedia entry (wow, he even has a wikipedia entry, complete with picture :))

There's a variant of Psychic Debugging called "Psychic Perf Analysis".  It works like this:

I get an IM from one of Ryan, one of the perf guys. 

Ryan: "Hey Larry, we just found a great perf bug that caused a 3 second slowdown in Windows boot time"

Me: "Let me guess, they were calling RegFlushKey in a service startup path."

<long pause>

Ryan: "Who told you?"

 

One of the things people don't realize about RegFlushKey is that it actually flushes the data that backs the registry key (doh!).  Well, flushing the data means that you need to write it to disk, and the semantics of RegFlushKey ensure that the data's actually been committed - in other words, the RegFlushKey API is going to block until all the disk writes needed to ensure that the data backing the key is physically on the disk.  This can take hundreds and hundreds of milliseconds.

In Ryan's case, it was complicated because the service was calling RegFlushKey from a DllMain function (Doh!) which held the loader lock, which meant that all the other services in that process were blocked, and there were other services that depended on those services, and...  You get the picture, it REALLY wasn't pretty.

The documentation for RegFlushKey explicitly says that "In general, RegFlushKey rarely, if ever, need be used", and it's right.

Why did I know that this was a problem?  Well, when we first deployed the new audio stack into Vista, we were blocked from RI'ing into winmain because the audio service degraded the boot time of Windows by 3/4 of a second (yes, we measure boot time performance to the millisecond, and changes that degrade the system boot performance aren't allowed in).  When I looked at the perf logs of the boot process, I noticed a significant number of writes occurring during the start of the audiosrv service.  I chased it down further, and realized that the writes correlated almost perfectly with some code that was modifying the registry.  I dug deeper and discovered a call to RegFlushKey that we had mistakenly added.  Removing the call to RegFlushKey fixed the problem.