2017-06-16, 07:54 AM
I'm monitoring when the NPVR PC wakes and saw that after the last recording of the "day/night" has finishes and the system went to sleep it wakes within 10 seconds without any recording being requested.
This is the output from the system event log showing sleep/wake (I added a powerdebug even to show the cause of waking) in reverse order.
You will notice that the system sleeps at 03:46:28 and is awake again at 03:47:28 (after updating the system time) and the wake cause was a timer set by NRecord
Looking at the NRecord log for that first wakeup (the intended recording wake)
you will notice the system sleeps at 3:47:33 but a wake timer has been set for 2:16 so the system wakes up immediately as also can be seen in the NRecord log for the second wake
This is also visible in the NPVR.log file where you see a going to standby at 03:46:27.938 and a wake from standby at 03:47:28.808
Now the question I have is: why is there a wake timer set in the past?
2017-06-16 02:16:37.775 [DEBUG][9] Requesting wake up for 'RecordingOID21702' at 6/16/2017 2:16 AM
Would that cause an immediate wake after going to standby at 3:47:33?
Log files attached
This is the output from the system event log showing sleep/wake (I added a powerdebug even to show the cause of waking) in reverse order.
Code:
Information,16-6-2017 03:47:29,Microsoft-Windows-Power-Troubleshooter,1,None,"The system has returned from a low power state.
Sleep Time: 2017-06-16T01:46:27.587929700Z
Wake Time: 2017-06-16T01:47:28.865922800Z
Wake Source: Timer - NRecord.exe"
Information,16-6-2017 03:47:28,Microsoft-Windows-Kernel-Power,131,(33),"Firmware S3 times. ResumeCount: 6, FullResume: 494, AverageResume: 495"
Information,16-6-2017 03:47:28,Microsoft-Windows-Kernel-General,1,(5),"The system time has changed to 2017-06-16T01:47:28.500000000Z from 2017-06-16T01:46:29.684025500Z.
Change Reason: System time synchronized with the hardware clock."
Error,16-6-2017 03:46:29,Microsoft-Windows-Kernel-Power,137,None,The system firmware has changed the processor's memory type range registers (MTRRs) across a sleep state transition (S4). This can result in reduced resume performance.
Information,16-6-2017 03:46:29,Microsoft-Windows-Kernel-Power,107,(102),The system has resumed from sleep.
Information,16-6-2017 03:46:28,Microsoft-Windows-Kernel-Power,42,(64),"The system is entering sleep.
Sleep Reason: System Idle"
Information,16-6-2017 02:16:30,Microsoft-Windows-Power-Troubleshooter,1,None,"The system has returned from a low power state.
Sleep Time: 2017-06-15T23:22:53.719826800Z
Wake Time: 2017-06-16T00:16:29.877550600Z
Wake Source: Timer - NRecord.exe"
Information,16-6-2017 02:16:29,Microsoft-Windows-Kernel-Power,131,(33),"Firmware S3 times. ResumeCount: 5, FullResume: 495, AverageResume: 495"
Information,16-6-2017 02:16:29,Microsoft-Windows-Kernel-General,1,(5),"The system time has changed to 2017-06-16T00:16:29.500000000Z from 2017-06-15T23:22:55.628596400Z.
Change Reason: System time synchronized with the hardware clock."
Error,16-6-2017 01:22:55,Microsoft-Windows-Kernel-Power,137,None,The system firmware has changed the processor's memory type range registers (MTRRs) across a sleep state transition (S4). This can result in reduced resume performance.
Information,16-6-2017 01:22:55,Microsoft-Windows-Kernel-Power,107,(102),The system has resumed from sleep.You will notice that the system sleeps at 03:46:28 and is awake again at 03:47:28 (after updating the system time) and the wake cause was a timer set by NRecord
Looking at the NRecord log for that first wakeup (the intended recording wake)
Code:
[...startup]
2017-06-16 02:16:36.213 [DEBUG][4] OnStart()
2017-06-16 02:16:36.225 [DEBUG][4] Checking if upgrade required
2017-06-16 02:16:36.235 [DEBUG][4] master file is C:\Users\Public\NPVR\Config-master-dont-edit.xml
2017-06-16 02:16:36.255 [INFO][4] Using local in-process recording service
2017-06-16 02:16:36.825 [DEBUG][4] CaptureSource.LoadAll()
2017-06-16 02:16:36.888 [DEBUG][4] RecordingServiceProxy@exit
2017-06-16 02:16:36.892 [INFO][4] RecordingService.Startup()
2017-06-16 02:16:36.892 [INFO][4] Starting remoting service (on port 8968)
2017-06-16 02:16:36.955 [DEBUG][10] Requesting wake up for 'EPGWAKEUP-backup' at 6/16/2017 7:21 AM
2017-06-16 02:16:36.955 [INFO][13] ServiceLocatorThread() starting
2017-06-16 02:16:36.955 [INFO][13] ServiceLocatorThread() starting
2017-06-16 02:16:36.955 [DEBUG][10] Requesting wake up for 'EPGWAKEUP' at 6/16/2017 7:21 AM
2017-06-16 02:16:36.965 [DEBUG][10] Next EPG update time: 6/16/2017 7:21 AM
2017-06-16 02:16:36.965 [INFO][13] ServiceLocatorThread() Hostname: Lambiekje
2017-06-16 02:16:37.005 [INFO][9] RecordingService starting...
2017-06-16 02:16:37.005 [DEBUG][9] Doing database vacuum
2017-06-16 02:16:37.212 [INFO][13] IP Address: 192.168.0.57
2017-06-16 02:16:37.212 [DEBUG][13] Waiting for broadcast
2017-06-16 02:16:37.492 [INFO][4] Starting web server on: 8866
2017-06-16 02:16:37.493 [INFO][4] Setting working directory to: C:\Program Files (x86)\NPVR\
2017-06-16 02:16:37.493 [INFO][4] Web root: C:\Users\Public\NPVR\web
2017-06-16 02:16:37.715 [DEBUG][9] vacuuming done
2017-06-16 02:16:37.725 [DEBUG][5] Deleting web temp files
2017-06-16 02:16:37.735 [DEBUG][9] No C:\Users\Public\NPVR\Scripts\PostStartup.bat
2017-06-16 02:16:37.735 [DEBUG][9] PurgeOldDeletes()
2017-06-16 02:16:37.735 [DEBUG][9] Loading recording schedule
2017-06-16 02:16:37.775 [DEBUG][9] CancelAllWakeupRequests
2017-06-16 02:16:37.775 [DEBUG][9] Requesting wake up for 'RecordingOID21702-backup' at 6/16/2017 2:17 AM
2017-06-16 02:16:37.775 [DEBUG][9] Requesting wake up for 'RecordingOID21702' at 6/16/2017 2:16 AM
2017-06-16 02:16:37.775 [DEBUG][9] Requesting wake up for 'RecordingOID21708-backup' at 6/16/2017 7:37 PM
.... Cut .....
2017-06-16 02:18:04.402 [DEBUG][9] Started recording (21702:1:K:\TV\Ripper Street\Ripper Street_20170616_02200315.ts)
2017-06-16 02:18:04.452 [DEBUG][9] Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "K:\TV\Ripper Street\Ripper Street_20170616_02200315.ts" 28 21702 61 "Ripper Street"
2017-06-16 02:18:04.492 [DEBUG][4] catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\Ripper Street.jpg</Poster><Landscape>C:\Users\Public\NPVR\media\shows\Ripper Street.landscape.jpg</Landscape><FanArt>C:\Users\Public\NPVR\media\shows\Ripper Street.fanart.jpg</FanArt><Banner>C:\Users\Public\NPVR\media\shows\Ripper Street.banner.jpg</Banner></Catalog>
2017-06-16 03:23:00.190 [DEBUG][9] Stopping recording (21702 on 61). Past end time of recording. 1
2017-06-16 03:23:00.240 [DEBUG][9] StopStream(1)
2017-06-16 03:23:01.062 [DEBUG][9] StoreMetaData@1
2017-06-16 03:23:01.081 [DEBUG][9] StoreMetaData@2
.. cut...
2017-06-16 03:23:01.091 [DEBUG][9] StoreMetaData@exit
2017-06-16 03:23:01.101 [DEBUG][9] Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "K:\TV\Ripper Street\Ripper Street_20170616_02200315.ts" 28 21702 61 "Ripper Street"
2017-06-16 03:47:28.737 [DEBUG][22] Resuming...
2017-06-16 03:47:30.185 [DEBUG][6] cycling MVP servers
2017-06-16 03:47:31.265 [DEBUG][21] OnStop()
2017-06-16 03:47:31.265 [DEBUG][21] About to stop webserver
2017-06-16 03:47:31.375 [DEBUG][21] webserver stopped
...cut ....
2017-06-16 03:47:31.385 [INFO][21] DigitalRecorder.StopAllStreams()
2017-06-16 03:47:31.385 [INFO][21] DigitalRecorder.StopAllStreams()
2017-06-16 03:47:33.387 [INFO][21] Recording Service hadnt stopped after 2000ms, continuing anyway
2017-06-16 03:47:33.597 [DEBUG][21] recording service stopped
2017-06-16 03:47:33.597 [DEBUG][21] OnStop() complete...Code:
[...startup]
2017-06-16 03:47:34.207 [DEBUG][4] OnStart()
2017-06-16 03:47:34.217 [DEBUG][4] Checking if upgrade required
2017-06-16 03:47:34.227 [DEBUG][4] master file is C:\Users\Public\NPVR\Config-master-dont-edit.xml
2017-06-16 03:47:34.247 [INFO][4] Using local in-process recording service
2017-06-16 03:47:34.630 [DEBUG][4] CaptureSource.LoadAll()
2017-06-16 03:47:34.709 [DEBUG][4] RecordingServiceProxy@exit
....cut.....This is also visible in the NPVR.log file where you see a going to standby at 03:46:27.938 and a wake from standby at 03:47:28.808
Code:
2017-06-16 03:44:31.840 [DEBUG][1] loading new bitmap data for: ListItemSelectedA Good Year
2017-06-16 03:44:31.842 [DEBUG][1] loading new bitmap data for: ListSelectionMetaData
2017-06-16 03:44:41.866 [DEBUG][1] loading new bitmap data for: ListSelectionMetaData
2017-06-16 03:46:27.938 [DEBUG][1] System is going into standby/hibernate
2017-06-16 03:47:28.500 [DEBUG][1] Recordings.RELOAD_RECORDINGS
2017-06-16 03:47:28.500 [DEBUG][1] Recordings.RELOAD_RECORDINGS@1
2017-06-16 03:47:28.500 [DEBUG][1] LoadList@0
2017-06-16 03:47:28.500 [DEBUG][1] LoadList@1
2017-06-16 03:47:28.554 [DEBUG][1] LoadList@2
2017-06-16 03:47:28.554 [DEBUG][1] LoadList@3
2017-06-16 03:47:28.664 [DEBUG][1] LoadList@setobjects
2017-06-16 03:47:28.664 [DEBUG][1] catalog says:
<Catalog><Version>1</Version></Catalog>
2017-06-16 03:47:28.694 [DEBUG][1] LoadList@exit
2017-06-16 03:47:28.694 [DEBUG][1] Recordings.RELOAD_RECORDINGS@2
2017-06-16 03:47:28.694 [DEBUG][1] catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\A Good Year.jpg</Poster><FanArt>C:\Users\Public\NPVR\media\shows\A Good Year.fanart.jpg</FanArt></Catalog>
2017-06-16 03:47:28.694 [DEBUG][1] PlaybackPositionHelper.GetLastPlaybackDate(K:\TV\A Good Year\A Good Year_20170606_20302302.ts)
2017-06-16 03:47:28.694 [DEBUG][1] PlaybackPositionHelper.GetPlaybackPosition(K:\TV\A Good Year\A Good Year_20170606_20302302.ts)
2017-06-16 03:47:28.746 [DEBUG][1] Recordings.RELOAD_RECORDINGS@exit
2017-06-16 03:47:28.808 [DEBUG][1] loading new bitmap data for: ListItemSelectedA Good Year
2017-06-16 03:47:28.808 [DEBUG][1] loading new bitmap data for: ListSelectionMetaData
2017-06-16 03:47:28.808 [DEBUG][1] Waking from standby/hibernate
2017-06-16 03:47:38.530 [DEBUG][1] loading new bitmap data for: ListSelectionMetaData
2017-06-16 03:49:28.517 [DEBUG][1] Recordings.RELOAD_RECORDINGS
2017-06-16 03:49:28.517 [DEBUG][1] Recordings.RELOAD_RECORDINGS@1Now the question I have is: why is there a wake timer set in the past?
2017-06-16 02:16:37.775 [DEBUG][9] Requesting wake up for 'RecordingOID21702' at 6/16/2017 2:16 AM
Would that cause an immediate wake after going to standby at 3:47:33?
Log files attached
P4 3GHz 1GB, 250GB, nVidia dualTV, GBPVR 1.3.11, XP
Support Comskip, visit the forum and donate at http://www.comskip.org/
Support Comskip, visit the forum and donate at http://www.comskip.org/