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.

Comments (19)

  1. Mike Dunn says:

    Looking at the Wikipedia pic:

    http://upload.wikimedia.org/wikipedia/en/6/6b/Raymond_Chen%2C_PDC05.jpg

    how many hands does Raymond have??!

  2. Björn says:

    Mike: The answer is 42.

  3. Gabe says:

    How do RegFlushKey calls end up in startup code for a service?

    Do you know what the purpose of putting them there was? The only use I can imagine for it is some sort of transactions, which would not likely have any business in startup code.

  4. James says:

    Larry,  why did the developers think to call RegFlushKey in the first place? This isn’t meant as a facetous question: unless the registry is being used for logging (which would seem inappropriate) or a complex scheme of transactionality is being implemented, I can’t think of a reason to do so. In the latter case, it would seem like there’s no solution that doesn’t involve committing.

    Assuming that this wasn’t redundant code, and that neither of the conditions above is true, I think this gets to the heart of my problem understanding the registry. I don’t understand how views of the registry are synchronised between applications. Consequently, I’ve always wished there was some kind of ‘sharing mode’ on registry keys, the same as for files. As things stand, the code I write relies on RegSetValue appearing atomic and goes to extreme measures to avoid relying on results of previous calls in order to read values, etc. It’s tricky, and there aren’t many hints in MSDN about doing it properly.

  5. AG says:

    On Exchange support late at night bouts of "Psychic Troubleshooting" were common.

    I believe the combo of coffee, Mountain Dew, and those instant ramon noodles brings out the latent Psychic powers in even the most feeble minded "C dash".

  6. Gabe/James, the RegFlushKey was added for the same reason that we accidentally added it into the audio stack – to ensure that the writes were flushed.  It’s just that there really isn’t normally a need to ensure that all the writes are flushed.

    And how did it get into the startup code for a service?  I don’t know, it was actually in the DllMain of a dependant DLL, it’s entirely possible that that DLL was owned by an unrelated team that didn’t realize that their code was called by a service.

  7. Richard says:

    > wow, he even has a wikipedia entry, complete with picture

    But you’re blog is linked to from at least one entry… http://en.wikipedia.org/wiki/Dancing_pigs_%28computer_security%29

  8. IEBlog says:

    As we worked towards the recent release of Internet Explorer 8 Beta 1, the IE team focused hard on performance.

  9. &#160; 최근 Internet Explorer 8 Beta 1 출시를 위해 개발중인 IE 팀은 성능에 심혈을 기울이고 있습니다. IE&#160; 향상을 위한 노력의 일환으로 실행한