Windows Explored

Everyday Windows Desktop Support, Advanced Troubleshooting & Other OS Tidbits

Investigating & Resolving Message Delays in Outlook with WinDbg

Posted by William Diaz on May 1, 2012


The problem starts after the user has had their Windows profile recreated but continues to experience some Outlook performance issues. Each time she clicks the New button in Outlook to create a new message, there is a 5 to 10 second delay before the blank message opens. There is also a 10+ second delay after she clicks send and Outlook becomes unresponsive for that time. I connect to her and quickly look at the Office Outlook registry for any unapproved 3rd party add-ins and see nothing out of the ordinary. I decide to dump the Outlook process when the hang is encounter and turn to Process Explorer. This is a simple matter of right-clicking the process and choosing Create Dump when it is in an unresponsive state. Actually, I collect two dumps, the other with Procdump in hang mode. I do this to ensure that the dumps are consistent; if the dumps are not similar then I may need to collect more until a pattern emerges.

I copied the dumps to my workstation and opened them with WinDbg and run the !analyze –v –hang command. The stack for both dumps are similar. With the exception of the NRTExchn component (our DMS add-in for Outlook), these are all MS modules. Normally, this wouldn’t excite me but something stands out like a sore thumb as I move up the stack, the presence of msi.dll in the stack of the current examine thread.

 

STACK_TEXT: 
0013ddc0 7c90d5aa 7c916887 0013de40 00100020 ntdll!KiFastSystemCallRet
0013ddc4 7c916887 0013de40 00100020 0013ddf8 ntdll!NtOpenFile+0xc
0013e08c 7c916bee 0b6cf8c8 0013e0b4 0013e000 ntdll!LdrpCheckForLoadedDll+0x43a
0013e108 7c916a1a 00000001 0b6cf8c8 00000000 ntdll!LdrGetDllHandleEx+0x258
0013e124 7c801d23 0b6cf8c8 00000000 0013e150 ntdll!LdrGetDllHandle+0x18
0013e18c 77c0169f 06d69bd8 00000000 00000002 kernel32!LoadLibraryExW+0x161
0013e1dc 1835c29b 06d69bd8 00000000 0000082c version!GetFileVersionInfoW+0x36
0013e238 1852d6e8 06d69bd8 00000000 0000082c clr!GetFileVersionInfoW_NoThrow+0x2c
0013e268 1852ed16 06d69bd8 0013e290 faa26515 clr!FusionGetFileVersionInfo+0x63
0013e2cc 7d25df96 0e9d56c0 00000000 00000002 clr!CAssemblyCache::QueryAssemblyInfo+0x1b5
0013e31c 7d1fb413 0b7a90c2 0e8e57b0 0013e4d0 msi!GetFusionPath+0x11d
0013e3dc 7d1ed94c 0013e868 00000000 0e8e57b0 msi!_GetComponentPath+0x798
0013e468 7d1f2d36 00000000 0013e868 0013e688 msi!GetComponentPath+0x107
0013e4b8 7d1f2cd8 00000000 0013e868 0013e688 msi!GetComponentPath+0x48
0013e720 7d1f277e 00000000 0013e868 0013e974 msi!QueryFeatureStatePacked+0x519
0013e8b0 7d1f2537 0013e9c4 0013e974 0013ea14 msi!ProvideComponent+0x146
0013ea68 7d1f2afe 0e85b5f0 00000000 0013eb6c msi!ProvideComponentFromDescriptor+0x1d8
0013eaa0 77dfbf24 0e85b5f0 0013eb6c 0013eb68 msi!MsiProvideComponentFromDescriptorW+0x6b
0013eb34 77554eaf 0e85b5f0 0013eb6c 0013eb68 advapi32!CommandLineFromMsiDescriptor+0x1c5
0013ed78 7756a2bf 0e85b5f0 0013edc0 0e9d9950 ole32!CComClassInfo::GetPathFromDarwinDescriptor+0xf8
0013ed98 77500081 00001b72 774ec400 0013edc0 ole32!CComClassInfo::GetDarwinIdentifier+0x37
0013ee58 774ffa72 0e9d9950 00000017 0013eea8 ole32!CComClassInfo::GetClassContext+0xec
0013eebc 774ff5af 77609e38 00000017 00000000 ole32!CComCatalog::GetClassInfoInternal+0x3e5
0013eee0 77500920 77609e38 098bf018 774e1974 ole32!CComCatalog::GetClassInfoW+0x1c
0013eef8 77500942 098bf018 0013ef14 098bf018 ole32!GetClassInfoFromClsid+0x24
0013ef18 774ff086 098bf018 0013efe8 04e25184 ole32!LookForConfiguredClsid+0x19
0013effc 774ff1a3 098bf018 00000000 00000007 ole32!ICoCreateInstanceEx+0x106
0013f024 774ff172 098bf018 00000000 00000007 ole32!CComActivator::DoCreateInstance+0x28
0013f048 774ff1e0 098bf018 00000000 00000007 ole32!CoCreateInstanceEx+0x1e
0013f078 09802ef3 098bf018 00000000 00000007 ole32!CoCreateInstance+0x37
WARNING: Stack unwind information not available. Following frames may be wrong.
0013f108 30cabd3a 0ea33fcc 01e895b8 098e8268 NRTExchn+0x32ef3
0013f138 301c4711 04e25184 01e895b8 04e2570c MSO!_MsoPvFree+0x129
0013f168 0980409c 00000000 301c66a7 074f5fe0 OUTLLIB!FFolderSupportsUnicode+0x3cca5
0013f1f8 301c67eb 0000f001 0013f22c 0013f21c NRTExchn+0x3409c
0013f244 301c6868 0000f001 00000000 00000009 OUTLLIB!FFolderSupportsUnicode+0x3ed7f
0013f29c 300589a4 0000f001 00000000 0013f2ec OUTLLIB!FFolderSupportsUnicode+0x3edfc
0013f2b8 301c6565 06c44f48 0000f001 00000001 OUTLLIB!XGetExplorerStoragePath+0x2d40
0013f2d0 301c3d66 06c44ef8 0000f001 00000008 OUTLLIB!FFolderSupportsUnicode+0x3eaf9
0013f308 301c2a18 04e2570c 04e25184 00000000 OUTLLIB!FFolderSupportsUnicode+0x3c2fa
0013f394 301bea25 04e25184 0013f3dc 301bf20f OUTLLIB!FFolderSupportsUnicode+0x3afac
0013f3a0 301bf20f 04e25604 04e25184 00000000 OUTLLIB!FFolderSupportsUnicode+0x36fb9

I guess correctly this is the Microsoft Windows Installer module:

0:000> lmvm msi
start    end        module name
7d1e0000 7d49c000   msi        (pdb symbols)          c:\windows\symbols\msi.pdb\668AD4E2E4404B9CA952C0813B22C32F2\msi.pdb
    Loaded symbol image file: msi.dll
    Mapped memory image file: c:\windows\symbols\msi.dll\4802A15A2bc000\msi.dll
    Image path: C:\WINDOWS\system32\msi.dll
    Image name: msi.dll
    Timestamp:        Sun Apr 13 20:12:10 2008 (4802A15A)
    CheckSum:         002BDB4B
    ImageSize:        002BC000
    File version:     3.1.4001.5512
    Product version:  3.1.4001.5512
    File flags:       8 (Mask 3F) Private
    File OS:          40004 NT Win32
    File type:        2.0 Dll
    File date:        00000000.00000000
    Translations:     0000.04b0
    CompanyName:      Microsoft Corporation
    ProductName:      Windows Installer – Unicode
    InternalName:     msi
    OriginalFilename: msi.dll
    ProductVersion:   3.1.4001.5512
    FileVersion:      3.1.4001.5512
    FileDescription:  Windows Installer
    LegalCopyright:   © Microsoft Corporation. All rights reserved.

Admittedly, this makes no sense to me. You normally see the Windows Installer kick in when something is being installed or uninstalled. Why it’s doing this in the process of Outlook opening new messages or sending messages is a mystery. But I should be able to get a clue as to what’s happening during this delay by looking up one of functions, specifically GetComponentPath. Looking up msi!GetComponentPath, MSDN states:

The MsiGetComponentPath function returns the full path to an installed component. If the key path for the component is a registry key then the registry key is returned.

I get the feeling that the delay/hang in Outlook is the result of various file query operations. Another clue are the frames that follow, also a file query type function:

0013e238 1852d6e8 06d69bd8 00000000 0000082c clr!GetFileVersionInfoW_NoThrow+0x2c
0013e268 1852ed16 06d69bd8 0013e290 faa26515 clr!FusionGetFileVersionInfo+0x63
0013e2cc 7d25df96 0e9d56c0 00000000 00000002 clr!CAssemblyCache::QueryAssemblyInfo+0x1b5

CLR is the Common Language Runtime, a component of the .NET Framework which is responsible for the execution of applications that are built on .NET. Maybe if I dump one of the parameters in the arguments I can see what file or keys are being looked at:

0013e31c 7d1fb413 0b7a90c2 0e8e57b0 0013e4d0 msi!GetFusionPath+0x11d
0013e3dc 7d1ed94c 0013e868 00000000 0e8e57b0 msi!_GetComponentPath+0x798
0013e468 7d1f2d36 00000000 0013e868 0013e688 msi!GetComponentPath+0x107
0013e4b8 7d1f2cd8 00000000 0013e868 0013e688 msi!GetComponentPath+0x48

:000> ddu 0013e868
0013e868 00460046
0013e86c 00440032
0013e870 00330030
0013e874 00320036
0013e878 00360042
0013e87c 00350046
0013e880 00450032

0013e8b8 0013e9c4 "{2630D2FF-5F6B-4EE2-A724-E07F33CF9977}"
0013e8bc 0013e974 "ITSM"
0013e8c0 0013ea14 "{0C603446-5F8F-41AF-806F-2BC08C9A7475}"
0013e8c4 00000000
0013e8c8 0013eb6e "D-AEC0-4AFF-84AF-4F61D15F5526}\InprocServer32"

ITSM stands out: this is our incident tracking client software and it is also a .NET application. There’s also a few guids here. Searching the first one confirms it is the product guid for ITSM:
image
Searching the registry for the partial guid, {741BEFED-AEC0-4AFF-84AF-4F61D15F5526}, reveals this is otherwise known as the Safe Replica of the Outlook’s MailItem. Looking inside it points to the ITSM Redemption DLL:
image
I happen to know that we also have a DLL of a same name but different version for another product that is also a .NET application, both of which are an application extension for Outlook. I compare this with another workstation that has ITSM installed, but here the other application (WorkShare) has populated InprocServer32 instead:
image
Although it shouldn’t matter which version of the DLL is being used to populate this key, as an experiment I decide to edit the registry of the workstation with the Outlook delay with the information of the WorkShare product. Interestingly, upon opening a new message, there was no longer a delay. There was, however, still a noticeable hang when sending an email; there were probably some additional guids or reg keys that are involved, but at this point it was no longer necessary to track them down. Instead, I should be able to resolve the issue by uninstalling ITSM. Upon doing so, it deleted the guid above. However, since this guid exists with the WorkShare product, running a scripted fix of WorkShare recreated the key. Afterwards, I was able to open a new message promptly and send it with no further delays. The real moment of truth, however, was to reinstall ITSM and then ensure the hangs did, in fact, not come back, and I was happy to see they didn’t.

I also took a look with Process Monitor just to see what files were also being queried during the new message delay. The dumped functions already alluded to this but you can specifically see 2500+ file operations in the .NET Global Assembly Cache (C:\Windows\Assembly), which accounts for 5 seconds of delay each time a new message was being opened in Outlook:
4-22-2012 1-00-25 AM
Looking at the stack of any of these operations produces a similar stack to that of the dump in WinDbg:

image
And finally, 100s of registry operations for installation data of the installed applications on the workstation:
image

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
%d bloggers like this: