Auto Deep Standby power timer issue

[Grumpy_Geoff]

I think that the Auto Deep Standby power timer backs off too soon and then never successfully sees that the 'problem' state is no longer existing.
Even a reboot doesn't fix it (perhaps a power timer is not updated to reflect the restart?).
Even if I delete and re-create.the Power Timer so that there is no former state, it never fires to deep standby.

It doesn't affect the Auto Standby timer as that fires as expected at the specified elapsed time (plus 3-min countdown).

Below power timer conditions -
Auto standby after 10 mins of remote control inactivity
Auto deep standby after 15 mins of remote control inactivity, and also active only in standby state.

The auto standby timer fires after 10 mins, counts down 3 mins, and the T-series goes then to standby
The auto deep standby timer immeditaely backs off at its first attempt after 15 mins - I would've expected it to fire then as the T2 is in standby. It never succeeds.

A timed 'go to deep standby' power timer works fine.


Another slight issue I noticed, is that if you press RED/Delete on a Power Timer, it is just disabled. You need to RED/Delete it again to actually delete it.

I don't think that either issue was the case in 4.4-land.

I've tried this on a T2 and T4 (20170310 and 20170422 firmwares).

Cheers
Geoff

[MrQuade]

I think that the Auto Deep Standby power timer backs off too soon and then never successfully sees that the 'problem' state is no longer existing.
Even a reboot doesn't fix it (perhaps a power timer is not updated to reflect the restart?).

Backs off too soon from what problem state? Was there was a missing opening paragraph from this post to provide some context?

I presume this was discovered as a result of tinkering during the T2 recording thread?

(Also, congrats on reaching 1337 status )

l337.png (12.35 KiB) Viewed 2188 times

[Grumpy_Geoff]

I think that the Auto Deep Standby power timer backs off too soon and then never successfully sees that the 'problem' state is no longer existing.
Even a reboot doesn't fix it (perhaps a power timer is not updated to reflect the restart?).

Backs off too soon from what problem state? Was there was a missing opening paragraph from this post to provide some context?

I presume this was discovered as a result of tinkering during the T2 recording thread?

(Also, congrats on reaching 1337 status )
l337.png

Actually, I just mangled the opening paragraph! It should backoff if currently recording, e.t.c, but that wasn't the case in my tests.
Yep, from Judy's thread. I'd seen the issue before and ignored it. Then the thread prompted me to retest.

For a new test, I added a new 'go to deep standby' power timer that had option "Auto deep standby timers only active when in standby" disabled - the timer fired as per specified delay, popped up the countdown timer, and the unit went to deep standby at the end of the countdown.
So it would appear the issue is with the timer detecting when the unit is in standby when that option is enabled.


Do I get beer for 'l337'?

[prl]

... and also active only in standby state.

Do you have logging enabled on the box and the logging to HDD? If so, it may be down to this (PowerTimer.py):

Code: Select all

				if ... or
					(self.autosleepinstandbyonly == 'yes' and Screens.Standby.inStandby and internalHDDNotSleeping())
				):
					self.do_backoff()

... Another slight issue I noticed, is that if you press RED/Delete on a Power Timer, it is just disabled. You need to RED/Delete it again to actually delete it.

I don't think that either issue was the case in 4.4-land.
...

I don't think it's new in 16.1, but I haven't quite worked out what's going on so I know what to look for in the change logs. But just because it's old doesn't mean it's not wrong.

[Grumpy_Geoff]

... and also active only in standby state.

Do you have logging enabled on the box and the logging to HDD? If so, it may be down to this (PowerTimer.py):

Code: Select all

				if ... or
					(self.autosleepinstandbyonly == 'yes' and Screens.Standby.inStandby and internalHDDNotSleeping())
				):
					self.do_backoff()

That'd be it. I'll disable logging and retest. Thanks.

[Grumpy_Geoff]

Not a bug! Turned off logging, and the T2 shut down at conclusion of recording once it had waited out its backoff time period. Forget that I said anything.

[MrQuade]

Not a bug! Turned off logging, and the T2 shut down at conclusion of recording once it had waited out its backoff time period. Forget that I said anything.

It might still be! I know the code shows that it does explicitly check for the harddisk to be sleeping, but like prl, I wonder if there is a specific reason for that? (and can that check simply be removed).

[prl]

Not a bug! Turned off logging, and the T2 shut down at conclusion of recording once it had waited out its backoff time period. Forget that I said anything.

It might still be! I know the code shows that it does explicitly check for the harddisk to be sleeping, but like prl, I wonder if there is a specific reason for that? (and can that check simply be removed).

I think the idea of the HDD sleep test is to make sure the system isn't shut down while the system is busy writing something to disk.

[MrQuade]

Surely the is a more elegant way of determining that you'd think though.

[prl]

If you can think of one, I'll try to implement it.

[MrQuade]

The other thing that bothered me about the behaviour that I forgot to add, was that a similar check is not performed when the "Auto deep standby timers only active when in standby" option is disabled. Now presumably, this is because otherwise the timer would never fire due to timeshift potentially being active. It just strikes me as strange that you'd suddenly start caring if the harddisk was doing anything only when in standby.

[peteru]

Like serving files using Samba or kernel NFS?

[MrQuade]

Like serving files using Samba or kernel NFS?

I suppose there is a use case where a user initiates a large file transfer then goes to standby with the expectation that the Wiz will then go to deep standby when done. But it still seems like a pretty blunt tool/check.

I don't have any better ideas to offer though.


Also, getting OT, but regarding "kernel NFS". Is there a way to serve NFS that works on the T series? I am still unable to make this work. (though I realise that you were perhaps referring to other brands/firmware where the feature does work properly)

[prl]

I think MrQuade's question is not "why is the HDD idle test done for an auto shutdown only if in standby?", but rather "why isn't the HDD idle test done for an auto shutdown in other circumstances?"

[Grumpy_Geoff]

I think MrQuade's question is not "why is the HDD idle test done for an auto shutdown only if in standby?", but rather "why isn't the HDD idle test done for an auto shutdown in other circumstances?"

Unless I'm not understanding this correctly, the T-series is likely to be showing live TV (thus writing timeshift buffers) or playing a recording or other media, so the HDD won't be idle. The user does get the 3-min warning. If not plating a service nor media, then likely a menu is open and the Power Timer won't fire in any case.

[prl]

I think MrQuade's question is not "why is the HDD idle test done for an auto shutdown only if in standby?", but rather "why isn't the HDD idle test done for an auto shutdown in other circumstances?"

Unless I'm not understanding this correctly, the T-series is likely to be showing live TV (thus writing timeshift buffers) or playing a recording or other media, so the HDD won't be idle. The user does get the 3-min warning. If not plating a service nor media, then likely a menu is open and the Power Timer won't fire in any case.

It's still a valid in-principle question and also points to the difficulty of answering the question when the PVR is in normal run mode.

[Grumpy_Geoff]

It appears debug logging is now no longer an impediment to a Power Timer auto-Deep-Standby/Shutdown timer.

I was using 'rsync' to copy recordings from a T2 to a network file share and left it running overnight.
This morning I noticed the PuTTY ssh session had been closed (but the window was still open), but the copy had completed.

Looking at the Power Timer log entry, I can see it was backing off and retrying every 30 mins until last backoff 1515526687/03:38:07 (AWST) and then retry 1515528487/04:08:07 where no further 'activity' was underway and the power timer actived 'state 3'/deep standby.
Debug logging was still active. I was suprised (but delighted) the rsync activity delayed the power timer deep standby action.
The T2 is still on (17.5) 20171204.

rsync result (I've highlighted when the ssh session was closed, 2 secs after the power timer activated) -

Code: Select all

sent 113,427,978,431 bytes  received 8,122 bytes  10,906,012.84 bytes/sec
total size is 113,400,244,338  speedup is 1.00
root@beyonwizt2:~#
The system is going down for system halt NOW!le) (Wed Jan 10 04:08:09 2018):
                                                             ********

Power Timer log snippet -

Code: Select all

<log code="5" time="1515523087">activating state 2</log>
<log code="10" time="1515523087">backoff: retry in 30 minutes</log>
<log code="5" time="1515524887">activating state 2</log>
<log code="10" time="1515524887">backoff: retry in 30 minutes</log>
<log code="5" time="1515526687">activating state 2</log>
<log code="10" time="1515526687">backoff: retry in 30 minutes</log>
<log code="5" time="1515528487">activating state 2</log>
<log code="5" time="1515528487">activating state 3</log>

[MrQuade]

Interesting. The blunt instrument has been sharpened somewhat?
Could that mean that it may be possible to check for harddisk activity (excluding timeshift) while not in standby?

[prl]

It appears debug logging is now no longer an impediment to a Power Timer auto-Deep-Standby/Shutdown timer.

I can't see any evidence that the effect of debug logging on autodeepstandby while in standby and with "Auto deep standby timers only active when in standby" enabled on the autodeepstandby timer has changed since 2014.

I was using 'rsync' to copy recordings from a T2 to a network file share and left it running overnight.
This morning I noticed the PuTTY ssh session had been closed (but the window was still open), but the copy had completed.

Looking at the Power Timer log entry, I can see it was backing off and retrying every 30 mins until last backoff 1515526687/03:38:07 (AWST) and then retry 1515528487/04:08:07 where no further 'activity' was underway and the power timer actived 'state 3'/deep standby.
Debug logging was still active. I was suprised (but delighted) the rsync activity delayed the power timer deep standby action.

I'd expect that. rsync causes disk activity & disk activity stops the HDD from going into standby, and if the HDD isn't in standby, the PowerTimer with the above settings will back off going into deep standby.

Peteru has done some cleaning-up of some excessive logging to the debug log. Perhaps the quietening-down of the logging has made it more likely that the HDD can spin down when in standby. The PowerTimer code that tests whether the HDD has spun down hasn't changed recently.

[MrQuade]

Peteru has done some cleaning-up of some excessive logging to the debug log. Perhaps the quietening-down of the logging has made it more likely that the HDD can spin down when in standby. The PowerTimer code that tests whether the HDD has spun down hasn't changed recently.

That sounds more likely.

[prl]

...
Could that mean that it may be possible to check for harddisk activity (excluding timeshift) while not in standby?

I don't know of any way to test for HDD activity that excludes I/O to particular files. The PowerTimer code doesn't (and probably shouldn't) even know what the names of the timeshift files are. The idle test simply looks at the read and write I/O operation counts in /sys/block/device/stat (1st & 5th fields) and checks whether their sum has stayed unchanged for at least the HDD "standby after" time.

[MrQuade]

I don't know of any way to test for HDD activity that excludes I/O to particular files. The PowerTimer code doesn't (and probably shouldn't) even know what the names of the timeshift files are. The idle test simply looks at the read and write I/O operation counts in /sys/block/device/stat (1st & 5th fields) and checks whether their sum has stayed unchanged for at least the HDD "standby after" time.

That was just speculation based on Geoff's observation that debugging was being ignored. But your subsequent post about the quieter debugging is probably closer to the truth.

[Grumpy_Geoff]

Peteru has done some cleaning-up of some excessive logging to the debug log. Perhaps the quietening-down of the logging has made it more likely that the HDD can spin down when in standby. The PowerTimer code that tests whether the HDD has spun down hasn't changed recently.

That sounds more likely.

Okay, that's likely it then - less aggressive logging.

root@beyonwizt2:~# grep standby /etc/enigma2/settings
config.usage.hdd_standby=600

I'm guessing the rsync command likely finished just before 4am,
No more logging after AutoTimer at time interval 85221 (03:55:34) until 'sdparm' at 85940, which is 12 mins later and HDD spin down is 10 mins.
Is sdparm checking for activity?
Then shut down to deep standby commences 35 seconds later.

Code: Select all

{626}< 85062.498> [Task] job Components.Task.Job name=AutoTimer #tasks=5 completed with [] in None
{626}< 85064.690> [NetworkTime] Updating
{626}< 85064.690> [Console] command: /usr/bin/ntpdate-sync
{626}< 85064.691> [eConsoleAppContainer] Starting /bin/sh
{626}< 85071.619> [Console] finished: /usr/bin/ntpdate-sync
{626}< 85071.620> [NetworkTime] setting E2 time: 1515527584.29
{626}< 85078.496> [eDVBLocalTimerHandler] no transponder tuned... or no TDT/TOT avail .. try to use RTC :)
{626}< 85078.497> [eDVBLocalTimerHandler] RTC time is 03:53:11
{626}< 85078.497> [eDVBLocalTimerHandler] Receiver time is 03:53:11
{626}< 85078.497> [eDVBLocalTimerHandler] RTC to Receiver time difference is 0 seconds
{626}< 85078.497> [eDVBLocalTimerHandler] no change needed
{626}< 85217.834> [AutoTimer][query] current auto poll 2018-01-10 03:55:30
{626}< 85217.835> [AutoTimer] Auto Poll Started
{626}< 85217.836> [AutoTimer] No changes in configuration, won't parse
{2383}< 85217.908> [eEPGCache] lookup events with 'Camp Lakebottom' in title (ignore case)
{626}< 85217.942> [AutoTimer][query] next auto poll at 2018-01-10 04:32:30
{776}< 85218.489> [eEPGCache] lookup events, title starting with '[R] Friends' (ignore case)
{7044}< 85219.212> [eEPGCache] lookup events with 'Regular Show' in title (ignore case)
{2383}< 85220.424> [eEPGCache] lookup events with 'Teen Titans' in title (ignore case)
{626}< 85221.345> [Task] job Components.Task.Job name=AutoTimer #tasks=5 completed with [] in None
{626}< 85940.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 85940.079> [eConsoleAppContainer] Starting sdparm
{626}< 85940.655> [Console] finished: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 85975.261> [InputHotplug] connectionLost? [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion: Connection lost.
]{626}< 85975.262> 
{626}< 85975.292> dvb time sync disabled... so set RTC now to current linux time! Wed 10 Jan 2018 04:08
{626}< 85975.300> set wakeup time to Wed 10 Jan 2018 04:15
{626}< 85975.301> PowerTimerWakeupAuto True
{626}< 85976.081> [AutoTimer] No changes in configuration, won't parse
{626}< 85976.116> [eDVBDB] ---- saving lame channel db

[prl]

...
Is sdparm checking for activity?
...

That would be sdparm being used to spin down the drive after Harddisk.runIdle() determines that the disk is idle. The HDD I/O stats are polled at 1/10 of the disk "standby after" time. As I said in my earlier post, HDD activity is checked by looking at the kernel's I/O stats for the drive.

Any idle spindown in the HDD itself is specifically disabled by Harddisk at startup time.

[Grumpy_Geoff]

...
Is sdparm checking for activity?
...

That would be sdparm being used to spin down the drive after Harddisk.runIdle() determines that the disk is idle. The HDD I/O stats are polled at 1/10 of the disk "standby after" time. As I said in my earlier post, HDD activity is checked by looking at the kernel's I/O stats for the drive.

Any idle spindown in the HDD itself is specifically disabled by Harddisk at startup time.

Okay, thanks.
From below 'sdparm' log entries, it appears the last external USB drive (/dev/sdb) spin down was at 21:27 (61940).
My earlier guess of the rsync command finishing just before 4am appears to be bollocks, given the internal drive (/dev/sda) spins down at 01:50 (77720).
I guess the later spin downs are due to disk actvity from logging occuring in-between the Power Timer 30-min retry intervals. Finally at just after 4am, we have shut down: propitious conditions extant

Code: Select all

{626}<    44.244> [Console] command: ('sdparm', 'sdparm', '--set=SCT=0', '/dev/sda')
{626}<    44.280> [Console] command: ('sdparm', 'sdparm', '--set=SCT=0', '/dev/sdb')
{626}<   800.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}<  2840.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}<  4580.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}<  5420.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}<  9080.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 10880.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 12620.080> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 15620.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 17540.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 22880.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 26600.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 27920.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 33680.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 36980.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 40880.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 57080.081> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 61940.080> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sdb')
{626}< 77720.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 79520.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 80360.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 82100.079> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 83900.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 84920.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')
{626}< 85940.078> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda')

The AutoTimer poll interval is 37 mins (but there are two groups of executions), the NTP update interval is the default 30 mins.
Perhaps if I had less granular AutoTimer and Network time scheduling I might get earlier shut downs - do you think?


Cheers,
Geoff