Re: exception following PowerOffSystem() call in power manager PDD

From: David Liao \(MS\) (davli_at_online.microsoft.com)
Date: 12/21/04 

Date: Mon, 20 Dec 2004 17:17:45 -0800

You are right, the exception is inside PowerOffSystem. In PowerOffSystem,
the driver's power callback is called. So, Most likely, it is device driver
power callback calling API.
Please turn on PNP zone on device.exe (of cause, you have to use debug
build). If you turn on pnp debug zon on device.exe, you should see
inforamtion like follows.

4294809112 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Powering Off system:
4294809113 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling GWES power proc.
4294809128 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling device manager
power proc.
4294809128 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling '<Unnamed>'
PowerDown at 0x34a6ed0
4294809129 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling '<Unnamed>'
PowerDown at 0x34a6ed0
4294809130 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'HCD5' PowerDown at
0x350e5e0
4294809131 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'HCD4' PowerDown at
0x350e5e0
4294809132 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'HCD3' PowerDown at
0x350e5e0
4294809135 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'HCD2' PowerDown at
0x350e5e0
4294809137 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'HCD1' PowerDown at
0x34cec90
4294809138 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling '<Unnamed>'
PowerDown at 0x357f5b0
4294809139 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'SCA1' PowerDown at
0x3d79a00
4294809140 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'NLD1' PowerDown at
0x3401f80
4294809141 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'BAT1' PowerDown at
0x3413950
4294809141 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling 'COM1' PowerDown at
0x3429840
4294809142 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling '<Unnamed>'
PowerDown at 0x3479cc0
4294809143 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling '<Unnamed>'
PowerDown at 0x3f32a20
4294809144 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling PmPowerHandler Off
4294809144 PID:43fcb0e6 TID:23f984e2 0x83fcacf0: Calling OEMPowerOff...

"Andrew Worsley" <Andrew.Worsley@nospam.4.me> wrote in message
news:MPG.1c31fdd13f00fcd29896ba@msnews.microsoft.com...
> In article <uOVxj5l5EHA.828@TK2MSFTNGP14.phx.gbl>, "David Liao \(MS\)"
> <davli@online.microsoft.com> says...
>> On Windows CE 4.2, you can't call any API during the power
>> callback(Except
>> few like SetInterruptEvent). The message indicate you are calling some
>> API
>> during the power callback. Usually, the problem is not the Power Manager
>> PDD, it is a driver. Probably, you have a driver which calling some API
>> in
>> XXX_PowerDown or XXX_PowerUp handler.
>>
>> You probably can find out which driver by turn on PNP zone on processor
>> device.exe.
>
> Thanks David,
>
> Sorry I replied by email - I meant to reply to the group, but must have
> pressed the wrong button.
>
> I was aware of that restriction (drivers can't call APIs during
> XXX_PowerDown()), but couldn't find any driver that
> breaks the rules. I'll tried turning on the PNP zone, but it didn't give
> any more information. In fact, I turned on all the device.exe zones, and
> all the pm.dll zones, and this is what I got:
>
> 4294844962 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PowerManager: Changing
> state from osrunning to osclosing because of Timeout
> 4294844963 PID:ffc0472 TID:6ff998ae 0x8ff968e0:
> +PmSetSystemPowerState_I: name osclosing, hint 0x00000000, options
> 0x00000000, fInternal 1
> 4294844966 PID:ffc0472 TID:6ff998ae 0x8ff968e0: ReadSystemPowerState:
> state 'osclosing' devices max is D4, flags 0x00200000
> 4294844967 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PmAlloc: alloc 28 bytes
> returned 0x00053010 (55 total objects allocated)
> 4294844969 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PmAlloc: alloc 36 bytes
> returned 0x00053040 (56 total objects allocated)
> 4294844971 PID:ffc0472 TID:6ff998ae 0x8ff968e0:
> RegReadClassDeviceRestrictions: reading information for class {98c5250d-
> c29a-4985-ae5f-afe5367e5006}
> 4294844973 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PmAlloc: alloc 44 bytes
> returned 0x00053080 (57 total objects allocated)
> 4294844975 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PmAlloc: alloc 24 bytes
> returned 0x000530c0 (58 total objects allocated)
> 4294844977 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PmAlloc: alloc 32 bytes
> returned 0x000530f0 (59 total objects allocated)
> 4294844979 PID:ffc0472 TID:6ff998ae 0x8ff968e0:
> RegReadClassDeviceRestrictions: device 'Default' restricted to D0
> 4294844981 PID:ffc0472 TID:6ff998ae 0x8ff968e0:
> RegReadClassDeviceRestrictions: reading information for class {a32942b7-
> 920c-486b-b0e6-92a702a99b35}
> 4294844983 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PmAlloc: alloc 44 bytes
> returned 0x00053130 (60 total objects allocated)
> 4294844985 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PmAlloc: alloc 24 bytes
> returned 0x00053170 (61 total objects allocated)
> 4294844987 PID:ffc0472 TID:6ff998ae 0x8ff968e0: PmAlloc: alloc 32 bytes
> returned 0x000531a0 (62 total objects allocated)
> 4294844989 PID:ffc0472 TID:6ff998ae 0x8ff968e0:
> RegReadClassDeviceRestrictions: device 'Default' restricted to D4
> 4294844991 PID:ffc0472 TID:6ff998ae 0x8ff968e0:
> RegReadClassDeviceRestrictions: skipping flags 0x00200000
> 4294844993 PID:ffc0472 TID:6ff998ae 0x8ff968e0: GenerateNotifications:
> sending type 1 notifications (32 bytes)
> 4294844996 PID:ffc0472 TID:6ff998ae 0x8ff968e0: SendNotification:
> sending notification to 0x000519c0 (owner 0x2fe444f6)
> 4294844997 PID:ffc0472 TID:6ff998ae 0x8ff968e0: GenerateNotifications:
> done sending type 1 notifications
> 4294844999 PID:ffc0472 TID:6ff998ae 0x8ff968e0: NotifyAndPowerOff():
> suspending - notifying non-block drivers
> 4294845000 PID:ffc0472 TID:6ff998ae 0x8ff968e0: DeviceStateAddRef:
> refcnt for 0x00037430 set to 3
> 4294845002 PID:ffc0472 TID:6ff998ae 0x8ff968e0: UpdateDeviceState: new
> state for 'nds0:' is 4 (current 0, req 0, set -1, floor 4, ceiling 4,
> actual 0)
> 4294845004 PID:ffc0472 TID:6ff998ae 0x8ff968e0: MapDevicePowerState:
> mapping D4 to D0
> 4294845005 PID:ffc0472 TID:6ff998ae 0x8ff968e0: SetDevicePower: setting
> 'nds0:' to D4 (mapped to D0), fForceSet is 0
> 4294845007 PID:ffc0472 TID:6ff998ae 0x8ff968e0: SetDevicePower: device
> is already at D0
> 4294845008 PID:ffc0472 TID:6ff998ae 0x8ff968e0: DeviceStateDecRef:
> refcnt for 0x00037430 set to 2
> 4294845009 PID:ffc0472 TID:6ff998ae 0x8ff968e0: DeviceStateAddRef:
> refcnt for 0x00037670 set to 2
> 4294845011 PID:ffc0472 TID:6ff998ae 0x8ff968e0: UpdateDeviceState: new
> state for 'vmini1' is -1 (current 0, req 0, set -1, floor 4, ceiling 0,
> actual 0)
> 4294845013 PID:ffc0472 TID:6ff998ae 0x8ff968e0: DeviceStateDecRef:
> refcnt for 0x00037670 set to 1
> 4294845015 PID:ffc0472 TID:6ff998ae 0x8ff968e0: NotifyAndPowerOff():
> calling KernelIoControl(IOCTL_HAL_PRESUSPEND)
> 4294845016 PID:cffdd59e TID:6ff998ae 0x8ff968e0: FS: Got Power notif
> 0x00000002
> 4294845018 PID:cffdd59e TID:6ff998ae 0x8ff968e0: FSREG: Registry flush
> unnecessary
> 4294845020 PID:cffdd59e TID:6ff998ae 0x8ff968e0: FSRAM: Flushing cached
> file data
> 4294845021 PID:ffc0472 TID:6ff998ae 0x8ff968e0: NotifyPowerOff():
> suspending - notifying block drivers
> 4294845023 PID:ffc0472 TID:6ff998ae 0x8ff968e0: DeviceStateAddRef:
> refcnt for 0x000524d0 set to 2
> 4294845025 PID:ffc0472 TID:6ff998ae 0x8ff968e0: UpdateDeviceState: new
> state for 'dsk1:' is 4 (current 0, req 0, set -1, floor 4, ceiling 4,
> actual 0)
> 4294845026 PID:ffc0472 TID:6ff998ae 0x8ff968e0: MapDevicePowerState:
> mapping D4 to D4
> 4294845028 PID:ffc0472 TID:6ff998ae 0x8ff968e0: SetDevicePower: setting
> 'dsk1:' to D4 (mapped to D4), fForceSet is 0
> 4294845029 PID:ffc0472 TID:6ff998ae 0x8ff968e0: RequestStreamDevice:
> calling DeviceIoControl(0x4fee6ce6) w/ request 3280904
> ('IOCTL_POWER_SET')
> 4294845031 PID:ffc0472 TID:6ff998ae 0x8ff968e0: ATADISK: Powering off
> system: D4 Count=1
> 4294845033 PID:ffc0472 TID:6ff998ae 0x8ff968e0: DeviceStateDecRef:
> refcnt for 0x000524d0 set to 1
> 4294845035 PID:ffc0472 TID:6ff998ae 0x8ff968e0: NotifyPowerOff():
> calling PowerOffSystem()
> 4294845036 PID:ffc0472 TID:6ff998ae Exception 040 Thread=8ff968e0 Proc=
> 0ffc0472 'device.exe'
> 4294845037 PID:ffc0472 TID:6ff998ae AKY=00000009 PC=8c9b2f4e RA=8c9b01f0
> TEA=00003b83
>
> As you can see, it is not until AFTER the call to PowerOffSystem() that
> the exception occurs.
>
> I thought it was Power Manager PDD that called the XXX_PowerDown()
> functions, right?
>
> I can step all the way through the Power Manger PDD code, past the calls
> to the UpdateClassDeviceStates() (is this what calls the XXX_PowerDown()
> functions?), right up to the call to PowerOffSystem(). Its only after
> stepping into that function that the exception occurs.
>
> Does the call to PowerOffStstem() cause other driver functions to be
> called? I thought all it did was set a flag, so the kernel calls
> OEMPowerOff() on the next reschedule.
>
> It is called like this (same as default driver, with some extra logging
> so I can see when it happens:
>
> FileSystemPowerFunction(FSNOTIFY_POWER_OFF);
>
> // update block device power states
> DEBUGMSG(ZONE_PLATFORM || ZONE_RESUME, (_T("NotifyPowerOff():
> suspending - notifying block drivers\r\n")));
> pdl = GetDeviceListFromClass(&idBlockDevices);
> if(pdl != NULL) {
> UpdateClassDeviceStates(pdl);
> }
>
>
> DEBUGMSG(ZONE_PLATFORM || ZONE_RESUME, (_T("NotifyPowerOff(): calling
> PowerOffSystem()\r\n")));
> PowerOffSystem(); // Set Flag in the system
> //Sleep(INFINITE); // Run the scheduler and never come back
> Sleep(0); // Run the scheduler and never come back
> DEBUGMSG(ZONE_PLATFORM || ZONE_RESUME, (_T("NotifyPowerOff(): returned
> from PowerOffSystem() - shouldn't get here!\r\n")));
>