Annotated pmdf log
25 Nov 08 SHL

Using acpi.psd 3.11 build dated 11 Nov 2008 21:13:42.
This is the second 3.11 build that replaced the ACPICA sources.

The output is messy becase we are running the COM port at 115K.
Desktop on Call overruns at this rate.

This is what we see it we just let the kernel run to the trap.

eax=ffebf300 ebx=ffeb64e4 ecx=fe4f8970 edx=00000000 esi=f9007a9c edi=00000000
eip=fff0628f esp=000049f8 ebp=f9007a60 iopl=0 -- -- -- nv up di pl nz ac po cy
cs=0178 ss=1530 ds=0170 es=0170 fs=0000 gs=0000 cr2=fa1a0000 cr3=00225000 p=00
0178:fff0628f cc             int     3
##ln
0178:fff06060 os2krnl:DOSHIGH32CODE:intIRQRouter + 22f
0178:fff06290 BeginIntHook - 1

##.lmo "acpi"
hmte=0097 pmte=%fd39dfccflags=8098a1c8 c:\acpi.psd
obj   vsize    vbase    flags   ipagemap cpagemap hob  sel
0001 0002aee2 f9ad0000 80002025 00000001 0000002b 0096 0488 r-x shr big
0002 000009d9 ffe50000 80001025 0000002c 00000001 0098 0490 r-x shr alias
0003 0000ae44 fe600000 80002021 0000002d 0000000b 0099 0498 r-- shr big
0004 00000496 ffe30000 80001003 00000038 00000001 0000 04a0 rw- alias
0005 0000cb60 f9c10000 80002003 00000039 00000001 0000 04a8 rw- big

##db 498:0
0498:00000000 4b 45 45 20 56 65 72 73-69 6f 6e 20 30 78 25 78 KEE Version 0x%x
0498:00000010 0a 00 00 00 0a 50 53 44-5f 69 6e 73 74 61 6c 6c .....PSD_install
0498:00000020 20 6f 70 74 69 6f 6e 73-3a 22 25 73 22 20 00 00  options:"%s" ..
0498:00000030 20 44 5 62 75 67 3a 25-78 20 00 00 0a 00 00 00  Debug:%......
0498:00000040 25 73 20 42 75 69 6c 64-20 4 61 74 65 3a 20 25 %s Build date: %
0498:00000050 73 20 25 73 0a 00 00 0-4e 6f 76 20 31 31 20 32 s %s....Nov 11 2
0498:00000060 30 30 38 00 32  3a 31-33 3a 34 32 00 00 00 00 008.21:13:42....
0498:00000070 4e 65 77 20 53 74 61 63-6b 20 3d 20 25 78 20 53 New Stack = %x S

The trap occurs because the interrupt router does not like being
entered when the spin lock is already held.

The logic that checks the spin lock state is present only in the debug
kernel.

This the same trap with breakpoints set to get useful stack trace.

eax=00000000 ebx=ffeb06da ecx=00000000 edx=00000000 esi=ffeb6f48 edi=fd3a9f98
eip=00001d7b esp=0000ffce ebp=0000ffd8 iopl=0 -- -- -- nv up ei pl zr na pe nc
cs=06a8 ss=15e8 ds=06a0 es=06a0 fs=0140 gs=0000 cr2=ffdeb000 cr3=00225000 p=00
06a8:00001d7b 0e             pu
Request was cancelled by user.
sh    cs

We Ctrl-C to get control when the kernel reports acpi.psd is loaded.

##bp InitGetBST
##g

We are in the "ScanBattery" logic.

##dd _SpinLocksOwned l1
0a00:00000fa4  ffffffff

No spin locks allocated.

##bp OS2UtMemAlloc
##g
eax=00000000 ebx=00010020 ecx=f9a0 edx=00000000 esi=00000002 edi=00000040
eip=f9addcfc esp=f9007aac ebp=f9007ad0 iopl=0 -- -- -- nv up di ng nz na pe cy
cs=0178 ss=1550 ds=0170 es=0170 fs=0000 gs=0000 cr2=fa1a0000 cr3=00225000 p=00
acpi:CODE32:Os2UtMemAllc:

The ACPICA logic needs memory to count references.

##dd _SpinLocksOwned l1
0a00:00000fa4  00000000

ACPICA holds spinlock

0178:f9addcfc 55             push   ebp              ;br1
##bp KernVMAlloc
##g

eax=00000001 ebx=f9007a90 ec0010000 edx=00000000 esi=f9007a9c edi=00000000
eip=fff15e50 esp=f9007a64 ebp=f90aa8 iopl=0 -- -- -- nv up di pl zr na pe nc
cs=0178 ss=1550 ds=0170 es=070 fs=0000 gs=0000 cr2=fa1a0000 cr3=00225000 p=00
os2krnl:DOSHIGH32CODE:KernVMAlloc:
0178:fff15e50 55             push      ebp              ;br2

acpi.psd is ready to request memory for ACPICA.

..snipped..

##p
eax=00000001 ebx=f9007a90 ecx=00010000 edx=00000000 esi=f9007a9c edi=00000000
eip=fff15e51 esp=f9007a60 ebp=f9007aa8 iopl=0 -- -- -- nv up di pl zr na pe nc
cs=0178 ss=1550 ds=0170 es=0170 fs=0000 gs=0000 cr2=fa1a0000 cr3=00225000 p=00
0178:fff15e51 8bec          mov       ebp,esp
##p
eax=00000001 ebx=f9007a90 ecx=00010000 edx=00000000 esi=f9007a9c edi=00000000
eip=fff15e53 esp=f9007a60 ebp=f9007a60 iopl=0 -- -- -- nv up di pl zr na pe nc
cs=0178 ss=1550 ds=0170 es=0170 fs=0000 gs=0000 cr2=fa1a0000 cr3=00225000 p=00
0178:fff15e53 8d65fc         lea       esp,[ebp-04]
##p
eax=00000001 ebx=f9007a90 ecx=00010000 edx=00000000 esi=f9007a9c edi=00000000
eip=fff15e56 esp=f9007a5c ebp=f9007a60 iopl=0 -- -- -- nv up di pl zr na pe nc
cs=0178 ss=1550 ds=0170 es=0170 fs=0000 gs=0000 cr2=fa1a0000 cr3=00225000 p=00
0178:fff15e56 8d45fc         lea       eax,[ebp-04]

Stack frame established

This is how we got here.

##k
0178:f9addd79 00010000 00000802 f9007a9c 00000000 Os2UtMemAlloc + 7d
0178:f9ad627f 00010000 00000000 f9007ad0 f9abbb10 AcpiOsAllocate + 18e
0178:f9ae2941 0000002c 0000000b 0000002c f9007ae8 AcpiUtAllocate + 3
0178:f9ae28f3 0000002c 00000001 fe60ac000019e AcpiUtAllocateZeroed + 1c
0178:f9af9e3a 0000002c 00000001 fe60acbc 0000019e AcpiOsAcquireObject + 9a
0178:f9ae5adf f9ac0070 f9007b50 0000000b f9007b50 AcpiUtCreateGenericState + 12
0178:f9ae5a5b 0000000b f9007b60 f9007b78 f9af7aae AcpiUtCreateUpdateState + a
0178:f9af7aae f9aaca70 f9a000 0000000b f9007b78 AcpiUtCreateUpdateStateAndPush + 1f
0178:f9aedd94 f9aaca70f9aa0000 f9007ba4 f9ac4c38 AcpiUtUpdateObjectReference + 94
0178:f9aeda01 f9abbb10 0000000 f9007bf0 f9ae82c2 AcpiUtAddReference + 21
0178:f9ae82c2 f9abbb10 f9007bf0 f9a4c38 00000000 AcpiExOpcode_2A_1T_1R + 326
0178:f9ae225f f9aa5fc0 f9aa5f0 00000000 f9aa5fe8 AcpiDsExecEndOp + ff
0178:f9af89cf f9aa5fc0 f9aa5fc000000000 f9aa5fc0 AcpiPsParseLoop + 2e9
0178:f9ae3af3 f9aa5fc0 9ac6a28 ffc6b200 f9aa5fc0 AcpiPsParseAml + ab
0178:f9adfca5 f9aa5fc0 000000 f9aca1b0 f9ac6a28 AcpiPsExecuteMethod + 217
0178:f9af4f58 f9ac6a28 9007cd8 00000005 f9aca1b0 AcpiNsEvaluate + f8
0178:f9af0536 f9ac6a28 00000005 faca1b0 ffe273b4 AcpiEvaluateObject + 130
0178:ffc50cc6 f9aca1b0 ffc51f680000000 f9007d28 InitGetBST + 33
0178:ffc50b35 f9aca1b0 f9aca1b0 00000000 edfe3e20 FindPowerObject + 11c
0178:f9af58d2 f9aca1b0 00000005f9007e3c 00000000 AcpiNsWalkNamespace + 92
0178:f9af0303 00000000 f9c1000 ffffffff 00000001 AcpiWalkNamespace + 4e
0178:ffc509a8 00000000 fffffff ffffffff ffc50a19 ScanBattery + 38
0178:ffc4f96d f9007e78 00000b2 0000007c f8df10b2 Init + 184
0178:ffc4f15e f8df10b4f00d483 01700000 068004b8 SendDDNotify + 45
0178:04b80170 007c0680 00b20000 000000 005b0000


##u fff15ef3
0178:fff15ef3 fb             sti
0178:fff15ef4 e851790a00     call      _dhw_VMInitAlloc (fffbd84a)
0178:fff15ef9 fa             cli
0178:fff15efa 668e1580e80ff mov       ss,word ptr [_KStack32Sel (ff800e98)]
0178:fff15f01 0325ac0a80ff   add       esp,dword ptr [_TKSSB (ff800aac)]
0178:fff15f07 c705ac0a80f00000000
	                     mov      dword ptr [_TKSSBase (ff800aac)],00000000
0178:fff15f11 fb             sti
0178:fff15f12 ebb7           jmp       fff15ecb
os2krnl:DOSHIGH32CODE:KernVMFree:
0178:fff15f14 55             push     ebp
0178:fff15f15 8bec           mov       ebp,esp
0178:fff15f17 8d65fc         lea     esp,[ebp-04]
0178:fff15f1a 8d45fc         lea   eax,[ebp-04]
##g fff15ef9

eax=ffebf300 ebx=ffeb64ecx=fe4f8970 edx=00000000 esi=f9007a9c edi=00000000
eip=fff0628f esp=00009f8 ebp=f9007a60 iopl=0 -- -- -- nv up di pl nz ac po cy
cs=0178 ss=1530 ds=0170 es=0170 fs=0000 gs=0000 cr2=fa1a0000 cr3=00225000 p=00
0178:fff0628f cc             int     3

We have died.

##dd CurrIntLevel l1
0a00:00000a8c  00000008
#dd InterruptLevel l1
0a00:00000a88  00000000

##ln
0178:fff06060 os2krnl:DOSHIGH32CODE:intIRQRouter + 22f
0178:fff06290 BeginIntHook - 1

##dd ebx l4
0170:ffeb64e4  fd39eee8 00007008 00000000 00000000

##ln ebx
0178:ffeb6464 os2krnl:DGROUP:airqi + 80

##dd airqi+80 l4
%ffeb64e4  fd39eee8 00007008 00000000 00000000