[Zgemma H9S] Deep standby time? Startup EPG problem

[Joe_90]

Possibly a red herring, but there are three adjustments if the box is booted from power off

May 10 12:22:56 zgemmah9s daemon.info avahi-daemon[1660]: Server startup complete. Host name is zgemmah9s.local. Local service cookie is 3000839176.
May 10 12:22:56 zgemmah9s daemon.info avahi-daemon[1660]: Service "FTP file server on zgemmah9s" (/services/ftp.service) successfully established.
May 10 14:48:54 zgemmah9s daemon.notice ntpdate[1602]: step time server 192.168.178.1 offset +8752.236760 sec
May 10 14:48:56 zgemmah9s daemon.info automount[1628]: key "logs" not found in map source(s).
May 10 14:48:58 zgemmah9s daemon.notice ntpdate[1714]: adjust time server 192.168.178.1 offset +0.000590 sec
May 10 14:49:02 zgemmah9s daemon.notice ntpdate[1729]: adjust time server 192.168.178.1 offset -0.000143 sec

I believe that the first one is the initial time setting [PID 1602], which comes from the network if-up.d call of ntpdate-sync. This has the "-b" parameter which forces a time step (although the man pages for ntpdate indicate the it will do a time step by default if the time difference is more than 0.5 seconds, otherwise it does a slew).
The second one [1714] comes from the default ntpdate-sync command which is issued by something in enigma. I asked a question about this in #58 above.
I think the third one [1729] may be happening because you have "sync by NTP" set, maybe? I don't see a third one in my startup, which is using "sync by transponder".

 

[Joe_90]

I have established why ntpdate-sync is taking so long to run. By default, the ntpdate command checks up to eight time servers to establish a reasonable guess at an accurate time. As an experiment I reduced that check to one time server. See below, where it took 2 seconds instead of the usual 8-9 seconds to run. You will note the ntpdate command stepped the time by default as it was just over a second out. The transponder time is slightly off.

May 10 16:30:01 ax61 authpriv.info crond[2343]: pam_unix(crond:session): session opened for user root(uid=0) by (uid=0)
May 10 16:30:01 ax61 cron.info CROND[2344]: (root) CMD (/usr/bin/ntpdate-sync silent)
May 10 16:30:01 ax61 user.notice root: ntpdate-sync running
May 10 16:30:01 ax61 user.notice root: ntpdate-sync checking ntpdate
May 10 16:30:03 ax61 cron.info CROND[2343]: (root) CMDOUT (10 May 16:30:03 ntpdate[2349]: step time server 188.125.64.7 offset +1.016450 sec)
May 10 16:30:03 ax61 cron.info CROND[2343]: (root) CMDEND (/usr/bin/ntpdate-sync silent)
May 10 16:30:03 ax61 authpriv.info CROND[2343]: pam_unix(crond:session): session closed for user root

I'm at the end of my limited expertise at this point. Foregrounding ntpdate-sync seems to be working to give me an accurate date/time and the debug log has the correct time in the filename.

 

[adm]

I believe that the first one is the initial time setting [PID 1602], which comes from the network if-up.d call of ntpdate-sync. This has the "-b" parameter which forces a time step (although the man pages for ntpdate indicate the it will do a time step by default if the time difference is more than 0.5 seconds, otherwise it does a slew).
The second one [1714] comes from the default ntpdate-sync command which is issued by something in enigma. I asked a question about this in #58 above.
I think the third one [1729] may be happening because you have "sync by NTP" set, maybe? I don't see a third one in my startup, which is using "sync by transponder".

I also had my time configured for NTP when I had 3 start up calls to to NTP but on the next test putting the box into deep standby for and hour then removing the power for an hour I only had 2 NTP calls on the next boot (resulting in the clock being two hours in the future). There seem some inconsistency between switch on from removed power.

 

[adm]

I have established why ntpdate-sync is taking so long to run. By default, the ntpdate command checks up to eight time servers to establish a reasonable guess at an accurate time. As an experiment I reduced that check to one time server. See below, where it took 2 seconds instead of the usual 8-9 seconds to run. You will note the ntpdate command stepped the time by default as it was just over a second out. The transponder time is slightly off.

If the NTP is taking 2 to 8 seconds to obtain a new value why do the offsets in the time shown in the message file only differ by 300 to 400 microseconds between the two NTP calls?

 

[Joe_90]

If the NTP is taking 2 to 8 seconds to obtain a new value why do the offsets in the time shown in the message file only differ by 300 to 400 microseconds between the two NTP calls?

Because there are two instances running (or finishing) at approximately the same time. ntpdateuses whatever value the system clock has at that instant, calculates an offset and steps the time to that value. Both instances have the same (old) clock value and calculate the same offset. The first instance to finish, steps the clock forward by that value. The clock now has the correct time. The second instance steps the clock forward by the same offset and the clock is now in the future. The problem here is that the clock is not being set to an actual time value - it's being stepped by a number of calculated seconds/microseconds.

I found that tweaking /usr/bin/ntpdate-sync to foreground the calls (by commenting out the "(" in line 55 and the ") &" in line 79 using a "#" is working great for me. I'm sure the devs will find a better way!

 

[Huevos]

So why allow multiple instances?

 

[Huevos]

e.g. try this: https://gist.github.com/beugley/43f3feb8c532f7cc07cbcb3ea3ccd203

 

[Huevos]

Or something like this to start the script:
ps -C script.name.sh > /dev/null 2>&1 || ./script.name.sh

 

[Joe_90]

Thanks @Huevos, but beyond my limited skill level. @birdman may have to investigate a bit deeper as to why multiple instances are fired.

 

[littlejim]

If ntpdate must set the clock by this adding/subtracting an offset method (rather than just asking the time and setting the clock to the answer obtained) then there should really be a semaphore making sure only one instance at a time is allowed to be in the middle of manipulating the clock.

 

[birdman]

At the moment I'm experimenting by commenting out the backgrounding in ntpdate-sync.

I take it you mean the one from the if-up.d scripts?

 

[birdman]

I just can't see the initial time stepping logged anywhere now.

syslog isn't running when the network comes up.

 

[birdman]

Question for @birdman. Does the following code in ntpdate-sync check that it is being called by if-up.d?

Yes.

It is setting the ntpdate option "-b" which forces a time step rather than a slew. I'm presuming calls to ntpdate-sync from other than if-up.d would/should just slew the time?

No.

As the comments says, the idea is that at boot time (and early in the boot time) you want the clock to be correct. So you slew it.

Later on you expect the time to be nearly right, so just make minor adjustments to the clock rate with the intentions of these heading towards zero.

This is from the ntpdate man page on Ubuntu (not necessarily exactly the same as the busybox version on Vix).

Time adjustments are made by ntpdate in one of two ways. If ntpdate determines the clock is in error more than 0.5 second it will simply step the time by calling the system settimeofday() routine. If the error is less than 0.5 seconds, it will slew the time by calling the system adjtime() routine. The latter technique is less disruptive and more accurate when the error is small, and works quite well when ntpdate is run by cron every hour or two.

 

[birdman]

So why allow multiple instances?

I've asked that at least twice already.

 

[birdman]

e.g. try this: https://gist.github.com/beugley/43f3feb8c532f7cc07cbcb3ea3ccd203

Not a reliable way to do it (it's not atomic).
Taking a file-system lock is far better.

EDIT: I meant "using the file-system to take the lock". It doesn't actually need to use filesystem locks.

 

[Joe_90]

I take it you mean the one from the if-up.d scripts?

I can only find one instance of the ntpdate-sync script. It's in /usr/bin/. Do you think there's another? Removing the backgrounding solves the issue for me completely. Those extra seconds of delay seem to prevent the collision between the two calls.

Do you know what is calling ntpdate-sync when it is logged in the debug log early after the start of enigma:

<    19.9117> 15:58:46.0095 [Console] command: /usr/bin/ntpdate-sync
<    19.9118> 15:58:46.0096 [eConsoleAppContainer] Starting /bin/sh
<    19.9123> 15:58:46.0100 [Console] pid = 2254

EDIT - in reference to the stepping and slewing - stepping happens first time (if called from if-up.d) and forced by the "-b" parameter. Slewing happens on subsequent runs, providing the time adjustment is less than 0.5 seconds, otherwise ntpdate steps the time. I've read the man pages and played with the various parameter settings.

 

[birdman]

I can only find one instance of the ntpdate-sync script. It's in /usr/bin/. Do you think there's another?

No.

But it occurs to me that adding code to ensure it's only running once at a time can be done quite simply within the ntpdate-sync script itself using standard commands.
I'll have a go this evening....

 

[Joe_90]

Thanks @birdman. Do you know what's calling ntpdate-sync from enigma as I asked in post #76?

 

[Huevos]

Thanks @birdman. Do you know what's calling ntpdate-sync from enigma as I asked in post #76?

Yes, I know what is calling ntp-sync. I fixed that already. Needs testing. But I think I will remove the cronjob.

 

[Huevos]

No.

But it occurs to me that adding code to ensure it's only running once at a time can be done quite simply within the ntpdate-sync script itself using standard commands.
I'll have a go this evening....

Don't bother with that.