TimeSVC and begin DST, one more time...

As I previously posted, our X86 platform experienced high processor loading
and a reset at 0200 hrs on August 19, 2006. This exhibited a signature
similar to the one that we previously observed when SNTP was enabled and
daylight saving time began 0200 hrs April 2, 2006. Hoping that the two are
truly the same, I created a debug build with SNTP, set the date to March 31,
2006 and recorded output when DST began (see below).

It is interesting that numerous messages are repetitively output by [NOTIFY]
and these coincide with a period of high processor loading (Our CEM app
reports 80% processor loading when this happens).

I would appreciate any insight that can be provided - particulary from any
MS folks.

0x86ca9b2c: --------------------------------------------------------------
0x86ca9b2c: | App Date Time Util Memory Memory |
0x86ca9b2c: | Id. dd-mmm-yyyy hh:mm:ss Time,% Avail,byte Delta,byte |
0x86ca9b2c: --------------------------------------------------------------
0x86ca9b2c: CEM> 02-Apr-2006 01:59:32 10.3 77873152 0
0x86ca9b2c: CEM> 02-Apr-2006 01:59:42 0.0 77873152 0
0x86ca9b2c: CEM> 02-Apr-2006 01:59:52 0.0 77873152 0
0x86f26800: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
01:59:52
0x86f29db4: NOTIFICATION::NewPacket attempt to exec
030021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
0x86f29db4: [NOTIFY] DeleteUserNotification 030021dd
0x86f29db4: [NOTIFY] DeleteUserNotification: 030021dd deleted
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTzChange
0x86e08c50: [NOTIFY] DeleteUserNotification 030021df
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTimeChange
0x86e08c50: [NOTIFY] DeleteUserNotification 030021de
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 12
app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
01:59:52
0x86f29db4: NOTIFICATION::NewPacket attempt to exec
040021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
0x86f29db4: [NOTIFY] DeleteUserNotification 040021dd
0x86f29db4: [NOTIFY] DeleteUserNotification: 040021dd deleted
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTzChange
0x86e08c50: [NOTIFY] DeleteUserNotification 040021de
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTimeChange
0x86e08c50: [NOTIFY] DeleteUserNotification 040021df
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 12
app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
01:59:52



0x86f29db4: NOTIFICATION::NewPacket attempt to exec
080021de:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
0x86f29db4: [NOTIFY] DeleteUserNotification 080021de
0x86f29db4: [NOTIFY] DeleteUserNotification: 080021de deleted
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTzChange
0x86e08c50: [NOTIFY] DeleteUserNotification 080021df
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTimeChange
0x86e08c50: [NOTIFY] DeleteUserNotification 080021dd
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 12
app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
01:59:59
0x86f29db4: NOTIFICATION::NewPacket attempt to exec
090021de:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
0x86f29db4: [NOTIFY] DeleteUserNotification 090021de
0x86f29db4: [NOTIFY] DeleteUserNotification: 090021de deleted
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTzChange
0x86e08c50: [NOTIFY] DeleteUserNotification 090021dd
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTimeChange
0x86e08c50: [NOTIFY] DeleteUserNotification 090021df
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 12
app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
fwpc.c - INTR_RTC
fwpc.c - SYSINTR_RTC_ALARM
0x86ca9b2c: --------------------------------------------------------------
0x86ca9b2c: | App Date Time Util Memory Memory |
0x86ca9b2c: | Id. dd-mmm-yyyy hh:mm:ss Time,% Avail,byte Delta,byte |
0x86ca9b2c: --------------------------------------------------------------
0x86ca9b2c: CEM> 02-Apr-2006 02:00:02 80.7 77873152 0
0x86ca9b2c: CEM> 02-Apr-2006 02:00:12 0.0 77873152 0
0x86ca9b2c: CEM> 02-Apr-2006 02:00:22 0.1 77873152 0

John
Wed Sep 27 11:45:25 CDT 2006

The amount of debug spew you're seeing from NOTIFY seems reasonable -- first
it's extremely verbose and when the time changes it has to go do a lot of
work (such as looking through all the scheduled events and see if they
should be fired right away). Notificitaion service uses the CE Database
extensively, so it's possible if the filesystem was very slow then this
could be the root cause of your problems. I don't think we've done explicit
perf tests on the notify subsystem on a known fast filesys unfortanutaly, so
I can't arbitrarily rule the scenario that it's too slow out either. Is
there any chance you could rerun the tests on say a RAM based filesystem?

Also for performance you should get the CPU #'s on a retail device because
stuff like all the Notification DEBUGMSG's, unoptimized code, extra
DEBUGCHK's, is going to slow things down.

--
John Spaith
Development Lead, Windows CE
Microsoft Corporation

Check out the CE Networking Team Blog at http://blogs.msdn.com/cenet/.

This posting is provided "AS IS" with no warranties, and confers no rights.
You assume all risk for your use. © 2006 Microsoft Corporation. All rights
reserved.

"Bill T" <BillT@discussions.microsoft.com> wrote in message
news:8DFE0509-6F52-4385-BED5-D43366A3A56E@microsoft.com...
> As I previously posted, our X86 platform experienced high processor
> loading
> and a reset at 0200 hrs on August 19, 2006. This exhibited a signature
> similar to the one that we previously observed when SNTP was enabled and
> daylight saving time began 0200 hrs April 2, 2006. Hoping that the two
> are
> truly the same, I created a debug build with SNTP, set the date to March
> 31,
> 2006 and recorded output when DST began (see below).
>
> It is interesting that numerous messages are repetitively output by
> [NOTIFY]
> and these coincide with a period of high processor loading (Our CEM app
> reports 80% processor loading when this happens).
>
> I would appreciate any insight that can be provided - particulary from any
> MS folks.
>
>
> x86ca9b2c: --------------------------------------------------------------
> 0x86ca9b2c: | App Date Time Util Memory Memory
> |
> 0x86ca9b2c: | Id. dd-mmm-yyyy hh:mm:ss Time,% Avail,byte Delta,byte
> |
>
> x86ca9b2c: --------------------------------------------------------------
> 0x86ca9b2c: CEM> 02-Apr-2006 01:59:32 10.3 77873152 0
> 0x86ca9b2c: CEM> 02-Apr-2006 01:59:42 0.0 77873152 0
> 0x86ca9b2c: CEM> 02-Apr-2006 01:59:52 0.0 77873152 0
> 0x86f26800: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> 01:59:52
> 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> 030021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> 0x86f29db4: [NOTIFY] DeleteUserNotification 030021dd
> 0x86f29db4: [NOTIFY] DeleteUserNotification: 030021dd deleted
> 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> for \\.\Notifications\NamedEvents\DSTTzChange
> 0x86e08c50: [NOTIFY] DeleteUserNotification 030021df
> 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> for \\.\Notifications\NamedEvents\DSTTimeChange
> 0x86e08c50: [NOTIFY] DeleteUserNotification 030021de
> 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> 12
> app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> 01:59:52
> 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> 040021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> 0x86f29db4: [NOTIFY] DeleteUserNotification 040021dd
> 0x86f29db4: [NOTIFY] DeleteUserNotification: 040021dd deleted
> 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> for \\.\Notifications\NamedEvents\DSTTzChange
> 0x86e08c50: [NOTIFY] DeleteUserNotification 040021de
> 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> for \\.\Notifications\NamedEvents\DSTTimeChange
> 0x86e08c50: [NOTIFY] DeleteUserNotification 040021df
> 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> 12
> app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> 01:59:52
>
>
>
> 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> 080021de:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> 0x86f29db4: [NOTIFY] DeleteUserNotification 080021de
> 0x86f29db4: [NOTIFY] DeleteUserNotification: 080021de deleted
> 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> for \\.\Notifications\NamedEvents\DSTTzChange
> 0x86e08c50: [NOTIFY] DeleteUserNotification 080021df
> 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> for \\.\Notifications\NamedEvents\DSTTimeChange
> 0x86e08c50: [NOTIFY] DeleteUserNotification 080021dd
> 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> 12
> app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> 01:59:59
> 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> 090021de:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> 0x86f29db4: [NOTIFY] DeleteUserNotification 090021de
> 0x86f29db4: [NOTIFY] DeleteUserNotification: 090021de deleted
> 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> for \\.\Notifications\NamedEvents\DSTTzChange
> 0x86e08c50: [NOTIFY] DeleteUserNotification 090021dd
> 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> for \\.\Notifications\NamedEvents\DSTTimeChange
> 0x86e08c50: [NOTIFY] DeleteUserNotification 090021df
> 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> 12
> app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> fwpc.c - INTR_RTC
> fwpc.c - SYSINTR_RTC_ALARM
>
> x86ca9b2c: --------------------------------------------------------------
> 0x86ca9b2c: | App Date Time Util Memory Memory
> |
> 0x86ca9b2c: | Id. dd-mmm-yyyy hh:mm:ss Time,% Avail,byte Delta,byte
> |
>
> x86ca9b2c: --------------------------------------------------------------
> 0x86ca9b2c: CEM> 02-Apr-2006 02:00:02 80.7 77873152 0
> 0x86ca9b2c: CEM> 02-Apr-2006 02:00:12 0.0 77873152 0
> 0x86ca9b2c: CEM> 02-Apr-2006 02:00:22 0.1 77873152 0

BillT
Wed Sep 27 13:27:01 CDT 2006

John

Thanks for the response.

I am a bit confused regarding your filesystem comment. My understanding is
that CE databases are located in the object store by default and the object
store is in RAM by default. We do not persist the object store in anyway (or
otherwise mess with it for that matter), so it seems that the database might
already be in RAM unless the notification database is somehow located
elsewhere. If it is, please let me know how to move it to RAM and I will run
tests to determine the effect of the move.

Actually, the 80% loading reported during this test is representative of
loading we have seen on the released product under these conditions.


"John Spaith [MS]" wrote:

> The amount of debug spew you're seeing from NOTIFY seems reasonable -- first
> it's extremely verbose and when the time changes it has to go do a lot of
> work (such as looking through all the scheduled events and see if they
> should be fired right away). Notificitaion service uses the CE Database
> extensively, so it's possible if the filesystem was very slow then this
> could be the root cause of your problems. I don't think we've done explicit
> perf tests on the notify subsystem on a known fast filesys unfortanutaly, so
> I can't arbitrarily rule the scenario that it's too slow out either. Is
> there any chance you could rerun the tests on say a RAM based filesystem?
>
> Also for performance you should get the CPU #'s on a retail device because
> stuff like all the Notification DEBUGMSG's, unoptimized code, extra
> DEBUGCHK's, is going to slow things down.
>
> --
> John Spaith
> Development Lead, Windows CE
> Microsoft Corporation
>
> Check out the CE Networking Team Blog at http://blogs.msdn.com/cenet/.
>
> This posting is provided "AS IS" with no warranties, and confers no rights.
> You assume all risk for your use. © 2006 Microsoft Corporation. All rights
> reserved.
>
> "Bill T" <BillT@discussions.microsoft.com> wrote in message
> news:8DFE0509-6F52-4385-BED5-D43366A3A56E@microsoft.com...
> > As I previously posted, our X86 platform experienced high processor
> > loading
> > and a reset at 0200 hrs on August 19, 2006. This exhibited a signature
> > similar to the one that we previously observed when SNTP was enabled and
> > daylight saving time began 0200 hrs April 2, 2006. Hoping that the two
> > are
> > truly the same, I created a debug build with SNTP, set the date to March
> > 31,
> > 2006 and recorded output when DST began (see below).
> >
> > It is interesting that numerous messages are repetitively output by
> > [NOTIFY]
> > and these coincide with a period of high processor loading (Our CEM app
> > reports 80% processor loading when this happens).
> >
> > I would appreciate any insight that can be provided - particulary from any
> > MS folks.
> >
> >
> > x86ca9b2c: --------------------------------------------------------------
> > 0x86ca9b2c: | App Date Time Util Memory Memory
> > |
> > 0x86ca9b2c: | Id. dd-mmm-yyyy hh:mm:ss Time,% Avail,byte Delta,byte
> > |
> >
> > x86ca9b2c: --------------------------------------------------------------
> > 0x86ca9b2c: CEM> 02-Apr-2006 01:59:32 10.3 77873152 0
> > 0x86ca9b2c: CEM> 02-Apr-2006 01:59:42 0.0 77873152 0
> > 0x86ca9b2c: CEM> 02-Apr-2006 01:59:52 0.0 77873152 0
> > 0x86f26800: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> > 01:59:52
> > 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> > 030021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> > 0x86f29db4: [NOTIFY] DeleteUserNotification 030021dd
> > 0x86f29db4: [NOTIFY] DeleteUserNotification: 030021dd deleted
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTzChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 030021df
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTimeChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 030021de
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> > 12
> > app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> > app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> > 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> > 01:59:52
> > 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> > 040021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> > 0x86f29db4: [NOTIFY] DeleteUserNotification 040021dd
> > 0x86f29db4: [NOTIFY] DeleteUserNotification: 040021dd deleted
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTzChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 040021de
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTimeChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 040021df
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> > 12
> > app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> > app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> > 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> > 01:59:52
> >
> >
> >
> > 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> > 080021de:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> > 0x86f29db4: [NOTIFY] DeleteUserNotification 080021de
> > 0x86f29db4: [NOTIFY] DeleteUserNotification: 080021de deleted
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTzChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 080021df
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTimeChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 080021dd
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> > 12
> > app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> > app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> > 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> > 01:59:59
> > 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> > 090021de:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> > 0x86f29db4: [NOTIFY] DeleteUserNotification 090021de
> > 0x86f29db4: [NOTIFY] DeleteUserNotification: 090021de deleted
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTzChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 090021dd
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTimeChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 090021df
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> > 12
> > app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> > app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> > fwpc.c - INTR_RTC
> > fwpc.c - SYSINTR_RTC_ALARM
> >
> > x86ca9b2c: --------------------------------------------------------------
> > 0x86ca9b2c: | App Date Time Util Memory Memory
> > |
> > 0x86ca9b2c: | Id. dd-mmm-yyyy hh:mm:ss Time,% Avail,byte Delta,byte
> > |
> >
> > x86ca9b2c: --------------------------------------------------------------
> > 0x86ca9b2c: CEM> 02-Apr-2006 02:00:02 80.7 77873152 0
> > 0x86ca9b2c: CEM> 02-Apr-2006 02:00:12 0.0 77873152 0
> > 0x86ca9b2c: CEM> 02-Apr-2006 02:00:22 0.1 77873152 0
>
>
>

BillT
Wed Sep 27 13:52:02 CDT 2006

John

Unfortunately I was unable to include all debug output from [NOTIFY] in my
original posting and there are actually 743 instances of the sequence shown
below. So there is quite a bit of debug output that could slow things down
but that fact that loading is similar for release builds suggests that isn't
the cause.

I am accessing this newsgroup via the web and don't know how to attach
files. This evening I will attach the debug output file to a posting set
form home via NNTP.

Thanks


0x86f26800: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
01:59:52
0x86f29db4: NOTIFICATION::NewPacket attempt to exec
030021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
0x86f29db4: [NOTIFY] DeleteUserNotification 030021dd
0x86f29db4: [NOTIFY] DeleteUserNotification: 030021dd deleted
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTzChange
0x86e08c50: [NOTIFY] DeleteUserNotification 030021df
0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
for \\.\Notifications\NamedEvents\DSTTimeChange
0x86e08c50: [NOTIFY] DeleteUserNotification 030021de
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 12
app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore


"John Spaith [MS]" wrote:

> The amount of debug spew you're seeing from NOTIFY seems reasonable -- first
> it's extremely verbose and when the time changes it has to go do a lot of
> work (such as looking through all the scheduled events and see if they
> should be fired right away). Notificitaion service uses the CE Database
> extensively, so it's possible if the filesystem was very slow then this
> could be the root cause of your problems. I don't think we've done explicit
> perf tests on the notify subsystem on a known fast filesys unfortanutaly, so
> I can't arbitrarily rule the scenario that it's too slow out either. Is
> there any chance you could rerun the tests on say a RAM based filesystem?
>
> Also for performance you should get the CPU #'s on a retail device because
> stuff like all the Notification DEBUGMSG's, unoptimized code, extra
> DEBUGCHK's, is going to slow things down.
>
> --
> John Spaith
> Development Lead, Windows CE
> Microsoft Corporation
>
> Check out the CE Networking Team Blog at http://blogs.msdn.com/cenet/.
>
> This posting is provided "AS IS" with no warranties, and confers no rights.
> You assume all risk for your use. © 2006 Microsoft Corporation. All rights
> reserved.
>
> "Bill T" <BillT@discussions.microsoft.com> wrote in message
> news:8DFE0509-6F52-4385-BED5-D43366A3A56E@microsoft.com...
> > As I previously posted, our X86 platform experienced high processor
> > loading
> > and a reset at 0200 hrs on August 19, 2006. This exhibited a signature
> > similar to the one that we previously observed when SNTP was enabled and
> > daylight saving time began 0200 hrs April 2, 2006. Hoping that the two
> > are
> > truly the same, I created a debug build with SNTP, set the date to March
> > 31,
> > 2006 and recorded output when DST began (see below).
> >
> > It is interesting that numerous messages are repetitively output by
> > [NOTIFY]
> > and these coincide with a period of high processor loading (Our CEM app
> > reports 80% processor loading when this happens).
> >
> > I would appreciate any insight that can be provided - particulary from any
> > MS folks.
> >
> >
> > x86ca9b2c: --------------------------------------------------------------
> > 0x86ca9b2c: | App Date Time Util Memory Memory
> > |
> > 0x86ca9b2c: | Id. dd-mmm-yyyy hh:mm:ss Time,% Avail,byte Delta,byte
> > |
> >
> > x86ca9b2c: --------------------------------------------------------------
> > 0x86ca9b2c: CEM> 02-Apr-2006 01:59:32 10.3 77873152 0
> > 0x86ca9b2c: CEM> 02-Apr-2006 01:59:42 0.0 77873152 0
> > 0x86ca9b2c: CEM> 02-Apr-2006 01:59:52 0.0 77873152 0
> > 0x86f26800: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> > 01:59:52
> > 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> > 030021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> > 0x86f29db4: [NOTIFY] DeleteUserNotification 030021dd
> > 0x86f29db4: [NOTIFY] DeleteUserNotification: 030021dd deleted
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTzChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 030021df
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTimeChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 030021de
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> > 12
> > app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> > app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> > 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> > 01:59:52
> > 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> > 040021dd:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> > 0x86f29db4: [NOTIFY] DeleteUserNotification 040021dd
> > 0x86f29db4: [NOTIFY] DeleteUserNotification: 040021dd deleted
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTzChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 040021de
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTimeChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 040021df
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> > 12
> > app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> > app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> > 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> > 01:59:52
> >
> >
> >
> > 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> > 080021de:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> > 0x86f29db4: [NOTIFY] DeleteUserNotification 080021de
> > 0x86f29db4: [NOTIFY] DeleteUserNotification: 080021de deleted
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTzChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 080021df
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTimeChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 080021dd
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> > 12
> > app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> > app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Setting event semaphore
> > 0x86e08c50: [NOTIFY] ProcessDatabase::started at local time 04/02/2006
> > 01:59:59
> > 0x86f29db4: NOTIFICATION::NewPacket attempt to exec
> > 090021de:\\.\Notifications\NamedEvents\ShellDSTEvent AppRunAtTime
> > 0x86f29db4: [NOTIFY] DeleteUserNotification 090021de
> > 0x86f29db4: [NOTIFY] DeleteUserNotification: 090021de deleted
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTzChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 090021dd
> > 0x86e08c50: [NOTIFY] CeRunAppAtEvent - clearing system event registration
> > for \\.\Notifications\NamedEvents\DSTTimeChange
> > 0x86e08c50: [NOTIFY] DeleteUserNotification 090021df
> > 0x86e08c50: [NOTIFY] RemoveAppRunAtTime::Starting Database Sweep...
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event
> > 12
> > app \\.\Notifications\NamedEvents\DSTTzChange args AppRunAfterTzChange
> > 0x86e08c50: [NOTIFY] SetUserNotification (or replacing 00000000)
> > 0x86e08c50: [NOTIFY] SetUserNotification::Registring system watch: event 1
> > app \\.\Notifications\NamedEvents\DSTTimeChange args AppRunAfterTimeChange
> > fwpc.c - INTR_RTC
> > fwpc.c - SYSINTR_RTC_ALARM
> >
> > x86ca9b2c: --------------------------------------------------------------
> > 0x86ca9b2c: | App Date Time Util Memory Memory
> > |
> > 0x86ca9b2c: | Id. dd-mmm-yyyy hh:mm:ss Time,% Avail,byte Delta,byte
> > |
> >
> > x86ca9b2c: --------------------------------------------------------------
> > 0x86ca9b2c: CEM> 02-Apr-2006 02:00:02 80.7 77873152 0
> > 0x86ca9b2c: CEM> 02-Apr-2006 02:00:12 0.0 77873152 0
> > 0x86ca9b2c: CEM> 02-Apr-2006 02:00:22 0.1 77873152 0
>
>
>

BillT
Thu Sep 28 12:26:02 CDT 2006

I attempted to attach the debug output to a posting and to send it via nntp
but it failed to be sent because the file is too large ~ 1mb.

"John Spaith [MS]" wrote:

> The amount of debug spew you're seeing from NOTIFY seems reasonable -- first
> it's extremely verbose and when the time changes it has to go do a lot of
> work (such as looking through all the scheduled events and see if they
> should be fired right away). Notificitaion service uses the CE Database
> extensively, so it's possible if the filesystem was very slow then this
> could be the root cause of your problems. I don't think we've done explicit
> perf tests on the notify subsystem on a known fast filesys unfortanutaly, so
> I can't arbitrarily rule the scenario that it's too slow out either. Is
> there any chance you could rerun the tests on say a RAM based filesystem?
>
> Also for performance you should get the CPU #'s on a retail device because
> stuff like all the Notification DEBUGMSG's, unoptimized code, extra
> DEBUGCHK's, is going to slow things down.
>
> --
> John Spaith
> Development Lead, Windows CE
> Microsoft Corporation
>
> Check out the CE Networking Team Blog at http://blogs.msdn.com/cenet/.
>
> This posting is provided "AS IS" with no warranties, and confers no rights.
> You assume all risk for your use. © 2006 Microsoft Corporation. All rights
> reserved.
>
> "Bill T" <BillT@discussions.microsoft.com> wrote in message
> news:8DFE0509-6F52-4385-BED5-D43366A3A56E@microsoft.com...