{"id":5933,"date":"2007-02-06T17:12:00","date_gmt":"2007-02-06T17:12:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/vcblog\/2007\/02\/06\/digging-into-problems\/"},"modified":"2019-02-18T18:54:36","modified_gmt":"2019-02-18T18:54:36","slug":"digging-into-problems","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/cppblog\/digging-into-problems\/","title":{"rendered":"Digging Into Problems"},"content":{"rendered":"

<\/p>\n

Hello my name is Steven Toscano, I am an SDET Tech Lead on the Visual C++ team.  <\/span>I am currently working in the IDE group focusing on improving our testing methodologies and expanding our library of tools.  <\/span>I’ve been a member of many teams across Visual C++ during my 7 year career including front-end, back-end optimizers, libraries (MFC, ATL, CRT), and now IDE.<\/p>\n

<\/span><\/p>\n

\n

<\/span><\/p>\n

 <\/p>\n

One of the many pleasures I get from doing my job is the ability to diagnose a problem and discover its root cause.  <\/span>I love digging into things as deep as I can until the asm is staring me in the face exposing those nasty little bugs.  <\/span>Sometimes going that deep isn’t necessary, sometimes you have to get creative about how to diagnose an issue.  <\/span>This is especially the case when you’re dealing with complex multi-threading bugs.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

One particular bug I looked into turned into a three day investigation.  <\/span>The net effect of the bug looked like this:<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

1. Open devenv<\/p>\n

<\/span><\/p>\n

2. Load a solution that contains two C++ projects<\/p>\n

<\/span><\/p>\n

3. Go to the Options dialog and set the “maximum number of parallel project builds” to 2 (I think this is the default if you’ve installed VS on a dual-processor machine)<\/p>\n

<\/span><\/p>\n

4. Build the solution<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

Result is an Access Violation at VCProjectEngine.dll!CBldFileRegEntry::ReleaseFRHRef()<\/b><\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

That’s right, the IDE just CRASHES!  <\/span>The worst possible behavior a customer could encounter (aside from data loss).  <\/span>And even better, this crash is not consistently reproducible; it might happen in 1 out of 100 times or not at all.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

So the typical process is to get exact repro steps, a full callstack when the AV hits and to attach a dump to the bug.  <\/span>After some quick searching in our bug database I found a bug with a similar callstack logged by someone outside our team about one month prior.  <\/span>I was a bit concerned because this bug was resolved as No Repro and included full dump info!<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

Since I was encountering this problem on my multi-proc machine I decided to take a deeper look.  <\/span>First of all the callstack up to the AV looked a bit weird.  <\/span>Notice the function at the top of the stack.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

>              <\/span>0996f4f3()               <\/span><\/p>\n

<\/span><\/b><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CBldFileRegEntry::ReleaseFRHRef<\/p>\n

<\/span><\/p>\n

                <\/span>VCProjectEngine.dll!CBldFileRegistry::LookupFile<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CVCBuildRegistryManipulator::LookupFile<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!GetFileFullPathI<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!GetFileFullPath<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CBldIncludeEntry::FindFile<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CVCToolImpl::ResolveIncludeDirectivesI<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CVCToolImpl::ResolveIncludeDirectivesToPath<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CLinkerLibrarianHelper::PickUpDeps<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CLinkerLibrarianHelper::DoGetDependencies<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CLinkerLibrarianHelper::DoGetAdditionalDependenciesInternal<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CVCLinkerTool::GetAdditionalDependenciesInternal<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CVCToolImpl::GetCommandLineOptions<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CVCToolImpl::GetCommandLineOptions<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CBldToolWrapper::GetCommandLineOptions<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CBldAction::RefreshCommandOptions<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CBldFileDepGraph::EnumerateBuildActionsI<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CBldFileDepGraph::RetrieveBuildActions<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CDynamicBuildEngine::DoBuild<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CDynamicBuildEngine::DoBuild<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CConfiguration::DoPreparedBuild<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CConfiguration::TopLevelBuild<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>VCProjectEngine.dll!CVCBuildThread::BuildThread<\/p>\n

<\/span><\/p>\n

 <\/span>               <\/span>kernel32.dll!BaseThreadStart<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/font><\/p>\n

<\/span><\/p>\n

Doesn’t resolve to symbol name and sure enough a check in the memory window shows this address is pointing into outer space.  <\/span>Here is the relevant source code at this point:<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/font><\/p>\n

<\/span><\/p>\n

void<\/span> CBldFileRegEntry::ReleaseFRHRef()<\/p>\n

<\/span><\/p>\n

{<\/p>\n

<\/span><\/p>\n

            <\/span>\/\/ Prevent access to registry by other threads.<\/p>\n

<\/span><\/span><\/p>\n

            <\/span>CritSectionT cs(g_sectionFileMap);<\/p>\n

<\/span><\/p>\n

            <\/span>if<\/span> (m_nRefCount <= 0)<\/p>\n

<\/span><\/p>\n

                        <\/span>return<\/span>;<\/p>\n

<\/span><\/p>\n

            <\/span>m_nRefCount–;<\/p>\n

<\/span><\/p>\n

            <\/span>if<\/span> (m_nRefCount == 0)<\/p>\n

<\/span><\/p>\n

           &nbsp\n;            <\/span>SafeDelete();<\/p>\n

<\/span><\/p>\n

}<\/span><\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/font><\/p>\n

<\/span><\/p>\n

The AV occurred when the SafeDelete function was called.  <\/span>I hit this bug once and left the debug session open on my machine for the whole three days.  <\/span>Given the working set tax of debugging this was slowing down my machine for my normal day-to-day duties, but I had to leave it just in-case I couldn’t repro it again.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

Drilling into this mysterious AV at a callsite, I thought it was bad code gen, here is the relevant asm for the ReleaseFRHRef function:<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/font><\/p>\n

<\/span><\/p>\n

if (m_nRefCount <= 0)<\/p>\n

<\/span><\/p>\n

5B00B14A  <\/span>mov         <\/span>eax,dword ptr [edi+18h] <\/p>\n

<\/span><\/p>\n

5B00B14D  <\/span>test        <\/span>eax,eax <\/p>\n

<\/span><\/p>\n

                                <\/span>return;<\/p>\n

<\/span><\/p>\n

5B00B14F  <\/span>jbe         <\/span>CBldFileRegEntry::ReleaseFRHRef+32h (5B00B15Eh) <\/p>\n

<\/span><\/p>\n

                <\/span>m_nRefCount–;<\/p>\n

<\/span><\/p>\n

5B00B151  <\/span>dec         <\/span>eax  <\/span><\/p>\n

<\/span><\/p>\n

5B00B152  <\/span>mov         <\/span>dword ptr [edi+18h],eax<\/span><\/p>\n

<\/span><\/p>\n

                <\/span>if (m_nRefCount == 0)<\/p>\n

<\/span><\/p>\n

5B00B155  <\/span>jne         <\/span>CBldFileRegEntry::ReleaseFRHRef+32h (5B00B15Eh) <\/p>\n

<\/span><\/p>\n

                                <\/span>SafeDelete();<\/p>\n

<\/span><\/p>\n

5B00B157  <\/span>mov         <\/span>eax,dword ptr [edi] <\/p>\n

<\/span><\/p>\n

5B00B159  <\/span>mov         <\/span>ecx,edi <\/p>\n

<\/span><\/p>\n

5B00B15B  <\/span>call        <\/span>dword ptr [eax+8]<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/font><\/p>\n

<\/span><\/p>\n

The last three instructions is the compiler generated code for a call through a vtable.  <\/span>Sure enough after debugging the code SafeDelete is the first virtual function call that we are making since we started executing code in this class.  <\/span>EDI is the this pointer, dereferencing that gives you the entry into the vtable.  <\/span>An offset of 8 on the vtable should give you back the address of the SafeDelete virtual function (since it’s the third vfunction).  <\/span>But as we can see indirecting that address gives the access violation.  <\/span>So someone trashed the contents of our object including the vtable.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

Now the question is who trashed our object?  <\/span>This was beginning to smell like a ref counting problem.  <\/span>I started to look at how the CBldFileRegEntry class was being used by looking at its implementation and where it is referenced.  <\/span>This class was retro-fitted to allow for simultaneous access through different threads.  <\/span>This was done through a shared reference or handle where\nuses of this handle were protected by Critical Sections sprinkled throughout the code.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

After Everett shipped the Visual C++ team started to work on parallel project building for the Whidbey product (see this blog<\/a> for details).  <\/span>This feature is great for multi-processor machines if you have a large solution with many leaf-node projects (i.e. projects that don’t have intra-dependencies).  <\/span>The set of classes that are on this callstack are some of the ones that were modified to get this functionality enabled in Whidbey.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

So all of this cool functionality but with random crashes?  <\/span>I had to take a deeper look at what was going on.  <\/span>The ref counting theory was beginning to make sense.  <\/span>If one thread had decremented the reference count too early another thread might think there are no references left to the shared object and delete it.  <\/span>While another thread is still using the object – and the next access to the object’s contents results in an AV right in the middle of the code.  <\/span>The fact that we’re seeing an AV is a good thing – Visual C++ 2005 will dirty the memory if you delete an object (filling it with sequences of 0xfeeefeee) imagine if that wasn’t the case – you wouldn’t see any crash just random incorrect behavior.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

There wasn’t much you could do with the information in the bug – if it was not easily reproducible you could not rerun the scenario and walk through the code.  <\/span>And with the dump that was attached you could only see the *end*<\/b> result – the thread that did the damage is long gone.<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

So I took a different approach and extracted the relevant pieces of the code into my own simulation.  <\/span>This was easy since the class was pretty self-contained, any references or dependencies to things that weren’t important I removed.  <\/span>Then I created a housing for the code – lifted straight off this MSDN article<\/a>.  <\/span>It was a simple app that created threads through the CreateThread() Win32 API.  <\/span>I set the number of threads to 30.  <\/span>And in my ThreadProc I added the code that accesses the shared resource the same way as the CBldFileRegEntry code.  <\/span>Sure enough I hit the AV like once every other run.  <\/span>So now I had a very consistent repro!<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/p>\n

<\/span><\/p>\n

With this little setup I was able to start closing in on the bug by using a binary search technique.  <\/span>I put a big Critical Section block around the first half of the code and left the rest as is.  <\/span>I ran the scenario and it didn’t repro (since that whole piece of code was blocking all threads!).  <\/span>Since it didn’t hit I tried the second half and it started to repro.  <\/span>Now that I had the right half I continued the process until I was down to a function level.  <\/span>Here was the suspect function:<\/p>\n

<\/span><\/p>\n

<\/p>\n

 <\/font><\/p>\n

<\/span><\/p>\n

BldFileRegHandle CBldFileRegFile::GetFileHandle(LPCOLESTR szFileName, BOOL bVerifyCase)<\/p>\n

<\/span><\/p>\n

{<\/p>\n

<\/span><\/p>\n

            <\/span>CPathW path;<\/p>\n

<\/span><\/p>\n

            <\/span>LPCOLESTR szKey;<\/p>\n

<\/span><\/p>\n

<\/span><\/p>\n

<\/span><\/p>\n","protected":false},"excerpt":{"rendered":"

Hello my name is Steven Toscano, I am an SDET Tech Lead on the Visual C++ team.  I am currently working in the IDE group focusing on improving our testing methodologies and expanding our library of tools.  I’ve been a member of many teams across Visual C++ during my 7 year career including front-end, back-end […]<\/p>\n","protected":false},"author":289,"featured_media":35994,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[],"class_list":["post-5933","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-cplusplus"],"acf":[],"blog_post_summary":"

Hello my name is Steven Toscano, I am an SDET Tech Lead on the Visual C++ team.  I am currently working in the IDE group focusing on improving our testing methodologies and expanding our library of tools.  I’ve been a member of many teams across Visual C++ during my 7 year career including front-end, back-end […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/posts\/5933","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/users\/289"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/comments?post=5933"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/posts\/5933\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/media\/35994"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/media?parent=5933"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/categories?post=5933"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/tags?post=5933"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}