Maarten's blog

Debugging with VMWare

2011-02-03T16:52:54Z

I normally use Windows Virtual PC for demos of Kernel debug scenarios. For a special occasion I needed to use VMWare. There are plenty of articles how to set it up and it is almost identical to Virtual PC. You basically connect over COM1 through a named pipe. But after hours of struggling I could not get it to work.

In the VM settings it says "Serial Port 2" which was somewhat weird already. Also in Device Manager on the VM it mentioned that the COM1 was already in use. Then I hit this article. Now I don't read Portuguese but the pictures are quite self-explanatory. Apparently when you have a printer connected to your machine, the first port is used by your printer. Adjusting the bcdedit settings fixed the problem.

ProcExp and XPerf tracing

2011-02-02T01:59:29Z

I was trying to run some XPerf traces to prepare for a training, when it all of a sudden stopped working. The error I got was this:

xperf: error: NT Kernel Logger: Cannot create a file when that file already exists. (0xb7).

Weird because I ran the same command successfully multiple times before. Trying to stop a potentially conflicting session by using:

Xperf –d blah.etl

Failed with this error:

xperf: error: Merge ETL: The specified path is invalid. (0xa1).

And the event log contained this:

Session "NT Kernel Logger" failed to start with the following error: 0xC0000035

What has changed was that I had started ProcMon.exe. That uses the NT Kernel Logger. Exiting that process cleared the way for my first command.

NX dependency on PAE

2011-01-07T00:18:57Z

Hardware supported NX is dependent on PAE (Windows Internals chapter 9. Memory). But why would that be?

The AMD64 Architecture Programmer's Manual (Volume 2: System Programming) mentions this:

No Execute (NX) Bit. Bit 63. This bit is present in the translation-table entries defined for PAE paging, with the exception that the legacy-mode PDPE does not contain this bit. This bit is not supported by non-PAE paging.

Again from Windows Internals we know that PTEs with PAE enabled are 64 bits long; without PAE they are only 32 bits long. There simply is no bit 63 for non-PAE paging. We can see it in the debugger.

Here is a call stack from the non-PAE crash dump:

0: kd> k

ChildEBP RetAddr

8292dc0c 968a1160 nt!KeBugCheckEx+0x1e

8292dc3c 968a1768 i8042prt!I8xProcessCrashDump+0x251

8292dc88 82840d4d i8042prt!I8042KeyboardInterruptService+0x2ce

8292dc88 8286449a nt!KiInterruptDispatch+0x6d

8292dd24 00000000 nt!KiIdleLoop+0x1a

If we dump out the the ChildEBP for the 2^nd frame:

0: kd> !pte 8292dc3c

VA 8292dc3c

PDE at C0300828 PTE at C020A4B4

contains 001BF063 contains 0292D963

pfn 1bf ---DA--KWEV pfn 292d -G-DA—KWEV

You see that the PTE contains a 32 bit value (0292D963).

The same exercise on a PAE enabled system gives us this call stack:

1: kd> k

ChildEBP RetAddr

807e1c0c 928bd160 nt!KeBugCheckEx+0x1e

807e1c3c 928bd768 i8042prt!I8xProcessCrashDump+0x251

807e1c88 828587cd i8042prt!I8042KeyboardInterruptService+0x2ce

807e1c88 8288101a nt!KiInterruptDispatch+0x6d

807e1d24 00000000 nt!KiIdleLoop+0x1a

The PTE here is 64 bit:

1: kd> !pte 807e1c3c

VA 807e1c3c

PDE at C0602018 PTE at C0403F08

contains 000000007A986863 contains 800000002D21F963

pfn 7a986 ---DA--KWEV pfn 2d21f -G-DA--KW-V

We would expect bit 63 on the ChildEBP to be set (EBP is on the stack and we would not want to execute any code from the stack: NX should be 1).

1: kd> .formats 800000002D21F963

Evaluate expression:

Hex: 80000000`2d21f963

Decimal: -9223372036097574557

Octal: 1000000000005510374543

Binary: 10000000 00000000 00000000 00000000 00101101 00100001 11111001 01100011

…

How about the return address of that same frame?

1: kd> !pte 928bd768

VA 928bd768

PDE at C06024A0 PTE at C04945E8

contains 0000000023615863 contains 000000007B9CD121

pfn 23615 ---DA--KWEV pfn 7b9cd -G--A—KREV

There the bit is not set:

1: kd> .formats 000000007B9CD121

Evaluate expression:

Hex: 7b9cd121

Decimal: 2073874721

Octal: 17347150441

Binary: 01111011 10011100 11010001 00100001

…

Note that .formats truncates the preceding 0s.

Install history in Reliability Monitor

2010-12-15T20:27:00Z

Yesterday I was running into a problem with Visual Studio 2010 and SilverLight 4. I asked for help internally. There was some suspician that this history might have something to do with my problem, but I had installed all kinds of tools on my machine over the last couple of weeks. Visual Studio 2008, 2010, Silverlight, Silverlight for Phone, etc. So I was grilled on when I installed what, and what order etc. I had no idea.

So I ask my friend Pat. He mentioned Reliability Monitor. So I type Windows key, "reliability", I select "View Reliability History" and I got this:

The nice thing is that it gives you a full history what went wrong, but also what is installed and when on the machine. You can even export an xml file and send it over or ask for it. This might come in handy when your mon/dad/aunt/neighbor claims that her/his machine magically became very sluggish without any user interaction.

Debugging Pool Leaks with X-Perf

2010-12-08T03:56:00Z

The WDK has a tool called poolmon and you can use it to find leaks as is described in the Windows Internals book. You can use the NotMyFault demo app (here) to demo it.

Instead of PoolMon you can also use WPT and X-Perf. Once installed, you run it like so:

xperf -on diageasy+pool -stackwalk PoolAlloc

Then you repro the leak. Once done you stop the trace with this:

xperf -d leaker.etl.

When you then open the trace in XPerfView, you will see four pool graphs in the fly-out:

When you go to one of the graphs, you'll see a nice jagged line in there. Hovering the mouse over the graph will show the pool tag associated with the pool allocations.

But there is more. When you select the jagged line in the graph, right-click and get the summary table you can actuall get the call stack. You have to rearrange the columns a bit. Pooltag first, then call stack will be good. Throw the type column to the right. Of course you need to have symbols loaded. But here is what you'll get:

This is obviously a convoluted scenario with a large frequent leak from NotMyFault. Nevertheless, it is easy to get to the culprit. If you have symbols for myfault.sys available, then you would right there and then have the function and source line.

Installing WPT (XPerf) from SDK

2010-11-17T15:50:00Z

This week I got a couple of requests how to install WPT from the SDK. You need to jump through some hoops.

If you bing "download xperf" you get here. In there it says to install from the SDK:

· Windows 7 SDK (contains WPT 4.6)

WPT 4.1.1 does not support Windows 7. Windows 7 SDK comes with a version compatible with this OS release. Please obtain WPT from the Platform SDK if you plan on analyzing performance traces from Windows 7 systems.

The MSIs containing these tools are installed as part of the Win32 Development Tools portion of the Windows SDK. You can use the Web installer to install just the Win32 Development Tools portion of the Windows SDK.

When you follow the link you get to this version of the SDK: but that is an older one. This is the later version 7.1 with framework 4.0.

So you start the web installer and select the following components.

When that finishes, the install is buried in the tools menu under Install Windows Performance Tools:

Getting IAT for all drivers from a Kernel Dump

2010-04-22T21:23:49Z

For some obscure reasons, I needed the Import Address Table (IAT) of specific modules from a kernel dump. Actually I needed them for all modules from potentially a whole lot of dumps. Getting the IAT for one module is straightforward:

Get the address of a module. For example for smb.sys
1: kd> lm msmb
start end module name
9c03e000 9c054000 smb
Dump the headers
1: kd> !dh /f 9c03e000

File Type: EXECUTABLE IMAGE
FILE HEADER VALUES
14C machine (i386)
7 number of sections
4A5BC903 time date stamp Mon Jul 13 16:53:39 2009

…

0 [ 0] address [size] of Special Directory
0 [ 0] address [size] of Thread Storage Directory
0 [ 0] address [size] of Load Configuration Directory
0 [ 0] address [size] of Bound Import Directory
C000 [ 1F4] address [size] of Import Address Table Directory
0 [ 0] address [size] of Delay Import Directory
0 [ 0] address [size] of COR20 Header Directory
0 [ 0] address [size] of Reserved Directory

Dump the IAT
1: kd> dds 9c03e000+C000 9c03e000+C000+1F4
9c04a000 82e06700 hal!KfAcquireSpinLock
9c04a004 82e086ee hal!KeGetCurrentIrql
9c04a008 82e067a0 hal!KfReleaseSpinLock
…

But that is all very manual. I would like to iterate over all modules in the dump and spit out the IAT to a text file or so. Excellent opportunity to finally learn WinDbg scripts. So here is the result:

$$ run like this: $$>a<" IAT.txt"

.logopen /t @"mylogfile.txt"

.echo =========================================

.echo Get IAT for all modules

.echo =========================================

$$ get offset of NT Header offset

r? $t1 = #FIELD_OFFSET(_IMAGE_DOS_HEADER , e_lfanew )

$$ get offset of OptionalHeader and store it

r? $t3 = #FIELD_OFFSET(_IMAGE_NT_HEADERS, OptionalHeader)

$$ get offset of DataDirectory and store

r? $t4 = #FIELD_OFFSET(_IMAGE_OPTIONAL_HEADER, DataDirectory)

$$ Iterate over each base address, get to the IAT address

!for_each_module "r $t0 = @#Base; .echo ==== @#ModuleName;

r $t2=poi(@$t0+@$t1);

r $t5=poi(@$t0+@$t2+@$t3+@$t4+0n12*0x8);

r $t6=poi(@$t0+@$t2+@$t3+@$t4+0n12*0x8+0x4);

dds @$t0 + @$t5 @$t0 + @$t5 + @$t6"

.logclose

There are probably better ways of doing this. But it gets the job done and I wrote my first script J. And the output

Opened log file 'D:\Playground7\OCA Reclassification\mylogfile_0820_2010-04-21_15-25-53-872.txt'

=========================================

Get IAT for all modules

=========================================

==== kdcom

80bc9000 82e1bfe4 hal!READ_PORT_UCHAR

80bc9004 82e1c04c hal!WRITE_PORT_UCHAR

…

Who changed my Platform Timer Resolution?

2010-03-01T01:36:00Z

When you run powercfg /energy from an elevated command line you can get this:

Warnings

Platform Timer Resolution:Platform Timer Resolution

The default platform timer resolution is 15.6ms (15625000ns) and should be used whenever the system is idle. If the timer resolution is increased, processor power management technologies may not be effective. The timer resolution may be increased due to multimedia playback or graphical animations.

Current Timer Resolution (100ns units)

25000

Maximum Timer Period (100ns units)

156001

Platform Timer Resolution:Outstanding Timer Request

A program or service has requested a timer resolution smaller than the platform maximum timer resolution.

Requested Period

30000

Requesting Process ID

8308

Requesting Process Path

\Device\HarddiskVolume4\Playground7\DebugTest\Debug\DebugTest.exe

From a power consumption persective, having an elevated more frequent timer might not be the most optimal.

Then in the informational section you get this:

Platform Timer Resolution:Timer Request Stack

The stack of modules responsible for the lowest platform timer setting in this process.

Requested Period	30000
Requesting Process ID	8308
Requesting Process Path	\Device\HarddiskVolume4\Playground7\DebugTest\Debug\DebugTest.exe
Calling Module Stack	\Device\HarddiskVolume2\Windows\SysWOW64\ntdll.dll
	\Device\HarddiskVolume2\Windows\SysWOW64\winmm.dll
	\Device\HarddiskVolume4\Playground7\DebugTest\Debug\DebugTest.exe
	\Device\HarddiskVolume2\Windows\SysWOW64\kernel32.dll
	\Device\HarddiskVolume2\Windows\SysWOW64\ntdll.dll

But that still doesn’t give me the source, nor what API to look for. One of the API calls that can be responsible for this is the timeBeginPeriod function. Then it becomes as easy as setting a breakpoint on winmm!timeBeginPeriod in WinDbg and voila. There might be more API calls that change the timer. [Edit] The more interesting API is obviously ntdll32!NtSetTimerResolution

My COM server is gone from Component Services (DCOMCNFG)

2010-01-15T19:09:00Z

Here’s a problem a partner ran into last month. Suppose you have an ActiveX server (in this case it was a VB6 COM Executable) registered on x64 bit Windows Server 2008 or Vista. You open up Component Services and you find your server under “Component Services\Computers\My Computer\DCOM Config”. Those same COM servers however don’t show up in that location under 64 bit versions of Windows 7 or Windows Server 2008 R2. How come?

First some background. When you register a COM server (myserver.exe /regserver), the server’s registration code has full control over what is entered in the registry. Most of the time frameworks such as ATL, MFC or VB take care of this in plumbing code. Apparently VB6 ActiveX servers don’t add the AppID. Spelunking around a little with procmon, the MMC snap-in for component services apparently enumerates all COM servers and adds the missing entries. It still does this on all platforms, so why the problem?

As mentioned this problem only manifests itself on x64 Windows 7 and Windows Server 2008 R2. The x64 bit versions of Vista and WS08 don’t manifest this problem. So what has changed? The answer is COM Reflection. When you register the COM Server on platforms prior to Windows 7 on an x64 system, the CLSID is copied from HKCR\Wow6432\CLSID to HKCR\CLSID. The MMC Component Services snap-in enumerates and fixes up only the “native” HKCR\CLSID. Since the values for 32 bit servers is no longer copied to that hive, you won’t see it in the 64 bit snap-in.

There is a trivial workaround for this. You can open a 32 bit mmc by typing “mmc -32” on the command line. Then add the Component Services snap-in from there. That will fix up the missing AppID entries. Once the entries are added you can use the 64 bit DCOMCNFG again.

Disabling a Shim (part II)

2009-07-29T19:15:18Z

Follow-up from the research on how to disable a per-application shim. When I saw the output from the shim infrastructure in DebugView, I mistakenly assumed that the application was shimmed. It apparently only means that the application is found in the AppCompat system database. It does not mean that the shim is actually still in place.

Which leaves me with the question, how do I easily verify that an application is not shimmed (short of the earlier mentioned shotgun approach of turning the whole shim engine off)? Someone who does this for a living told me that one way you can tell is whether aclayers.dll is loaded in the process. He also told me that getting an application shim free is not that easy. There are all kinds of watchdogs in the system monitoring and instrumenting applications.

When an application entry is disabled in ACT, I see with Process Explorer two environment variables that indicate to me they have something to do with Application Compatibility or shimming: __COMPAT_LAYER = VistaSetup and SHIM_DEBUG_LEVEL = 9. The last one was added by me for the logging. I also see AcGeneral.dll and apphelp.dll loaded in the process. And it is wrapped in a job (you can tell by looking at the process properties in Process Explorer; there is a Job tab).

When I reenable the entry, I see __COMPAT_LAYER=VistaSetup WinXPSp2_GW and the same SHIM_DEBUG_LEVEL=9. This WinXPSp2_GW matches the entry in the ACT database. This somewhat confirms that disabling an entry does indeed have the desired effect. Also an additional dll was loaded: the before mentioned aclayers.dll.

When the PCA notices your application as a setup, it will flag it in the registry. This was my case and I was thinking maybe, the VistaSetup CompatLayer comes from there. I made sure the application was not flagged anywhere under (\AppCompatFlags\Compatibility Assistant\Persisted.) No difference. VistaSetup was still there.

Then I disabled the Program Compatibility Assistant service. The effect of that was that the process is no longer wrapped inside a job. However the service restarts quickly. I had to disable it to make sure it didn't get in the way. Still the VistaSetup was there as an environment variable.

My current assumption is that the VistaSetup layer is coming from the fact that there is no Windows 7 switchback entry in the manifest. It apparently is also detected as a setup. I will need to verify it by adding the switchback GUID. That is for next time.

Current Timer Resolution (100ns units)	25000
Maximum Timer Period (100ns units)	156001