[SOLVED] Astro Binding - Event Drift

vzorglub · April 30, 2018, 6:43pm

Hello,
Has anyone noticed the slight time drift in Astro Events:
From 30ms to 45ms drift every 5 minutes

2018-04-30 17:36:52.955 [vent.ItemStateChangedEvent] - SunAzimuth changed from 262.15 to 263.18
2018-04-30 17:41:53.000 [vent.ItemStateChangedEvent] - SunAzimuth changed from 263.18 to 264.20
2018-04-30 17:46:53.042 [vent.ItemStateChangedEvent] - SunAzimuth changed from 264.20 to 265.21
2018-04-30 17:51:53.060 [vent.ItemStateChangedEvent] - SunAzimuth changed from 265.21 to 266.22
2018-04-30 17:56:53.093 [vent.ItemStateChangedEvent] - SunAzimuth changed from 266.22 to 267.21
2018-04-30 18:01:53.090 [vent.ItemStateChangedEvent] - SunAzimuth changed from 267.21 to 268.21
2018-04-30 18:06:53.113 [vent.ItemStateChangedEvent] - SunAzimuth changed from 268.21 to 269.19
2018-04-30 18:11:53.211 [vent.ItemStateChangedEvent] - SunAzimuth changed from 269.19 to 270.18
2018-04-30 18:16:53.241 [vent.ItemStateChangedEvent] - SunAzimuth changed from 270.18 to 271.15
2018-04-30 18:21:53.338 [vent.ItemStateChangedEvent] - SunAzimuth changed from 271.15 to 272.13
2018-04-30 18:26:53.378 [vent.ItemStateChangedEvent] - SunAzimuth changed from 272.13 to 273.10
2018-04-30 18:31:53.422 [vent.ItemStateChangedEvent] - SunAzimuth changed from 273.10 to 274.06
2018-04-30 18:36:53.458 [vent.ItemStateChangedEvent] - SunAzimuth changed from 274.06 to 275.03
2018-04-30 18:41:53.484 [vent.ItemStateChangedEvent] - SunAzimuth changed from 275.03 to 275.99
2018-04-30 18:46:53.500 [vent.ItemStateChangedEvent] - SunAzimuth changed from 275.99 to 276.95
2018-04-30 18:51:53.532 [vent.ItemStateChangedEvent] - SunAzimuth changed from 276.95 to 277.91
2018-04-30 18:56:53.556 [vent.ItemStateChangedEvent] - SunAzimuth changed from 277.91 to 278.86
2018-04-30 19:01:53.573 [vent.ItemStateChangedEvent] - SunAzimuth changed from 278.86 to 279.82
2018-04-30 19:06:53.617 [vent.ItemStateChangedEvent] - SunAzimuth changed from 279.82 to 280.77
2018-04-30 19:11:53.626 [vent.ItemStateChangedEvent] - SunAzimuth changed from 280.77 to 281.73
2018-04-30 19:16:53.653 [vent.ItemStateChangedEvent] - SunAzimuth changed from 281.73 to 282.68
2018-04-30 19:21:53.700 [vent.ItemStateChangedEvent] - SunAzimuth changed from 282.68 to 283.63
2018-04-30 19:26:53.727 [vent.ItemStateChangedEvent] - SunAzimuth changed from 283.63 to 284.59
2018-04-30 19:31:53.751 [vent.ItemStateChangedEvent] - SunAzimuth changed from 284.59 to 285.55
2018-04-30 19:36:53.789 [vent.ItemStateChangedEvent] - SunAzimuth changed from 285.55 to 286.50

It is only me?

mhilbush · May 1, 2018, 11:18am

No, it’s not just you. I see a drift of about 7 to 8 ms per execution, but I’m running on a 4.2 GHz CPU.

The astro binding uses scheduleWithFixedDelay for the positional job, which schedules the job starting from the termination of the previous job to the commencement of the next job. That would suggest that the execution time of the job will introduce some drift between executions. I wonder if it should be using scheduleAtFixedRate instead.

@gerrieg or @kai WDYT?

Kai · May 1, 2018, 5:25pm

Sounds like a logical explanation! Could you file an issue at ESH, please?

vzorglub · May 1, 2018, 5:43pm

Issue raised on Github #3534

mhilbush · May 1, 2018, 9:36pm

@vzorglub Thanks for opening the issue.

mhilbush · May 1, 2018, 10:01pm

I see the issue was opened in the wrong repo. I opened it in the ESH repo.

github.com/eclipse-archived/smarthome

[astro] Time drift on positional job

opened 10:00PM - 01 May 18 UTC

closed 05:44AM - 07 May 18 UTC

mhilbush

bug help wanted Binding-Astro

The sun elevation is supposed to be calculated at a regular frequency (default i…s every 300s). However, due to the use of `scheduleWithFixedDelay` for the positional job, which schedules the job starting from the termination of the previous job to the commencement of the next job, there is a small time drift introduced. This time drift can be anywhere from a few milliseconds to 35-40 milliseconds per execution, depending on the CPU speed. Example of drift: ``` 2018-04-30 17:36:52.955 [vent.ItemStateChangedEvent] - SunAzimuth changed from 262.15 to 263.18 2018-04-30 17:41:53.000 [vent.ItemStateChangedEvent] - SunAzimuth changed from 263.18 to 264.20 2018-04-30 17:46:53.042 [vent.ItemStateChangedEvent] - SunAzimuth changed from 264.20 to 265.21 2018-04-30 17:51:53.060 [vent.ItemStateChangedEvent] - SunAzimuth changed from 265.21 to 266.22 2018-04-30 17:56:53.093 [vent.ItemStateChangedEvent] - SunAzimuth changed from 266.22 to 267.21 2018-04-30 18:01:53.090 [vent.ItemStateChangedEvent] - SunAzimuth changed from 267.21 to 268.21 2018-04-30 18:06:53.113 [vent.ItemStateChangedEvent] - SunAzimuth changed from 268.21 to 269.19 2018-04-30 18:11:53.211 [vent.ItemStateChangedEvent] - SunAzimuth changed from 269.19 to 270.18 2018-04-30 18:16:53.241 [vent.ItemStateChangedEvent] - SunAzimuth changed from 270.18 to 271.15 2018-04-30 18:21:53.338 [vent.ItemStateChangedEvent] - SunAzimuth changed from 271.15 to 272.13 2018-04-30 18:26:53.378 [vent.ItemStateChangedEvent] - SunAzimuth changed from 272.13 to 273.10 2018-04-30 18:31:53.422 [vent.ItemStateChangedEvent] - SunAzimuth changed from 273.10 to 274.06 2018-04-30 18:36:53.458 [vent.ItemStateChangedEvent] - SunAzimuth changed from 274.06 to 275.03 ``` This drift could be eliminated (or greatly reduced) by the use of `scheduleAtFixedRate` instead of `scheduleWithFixedDelay`. The guidelines indicate `scheduleWithFixedDelay` is preferred. However, as the astro binding performs accurate calculations, it can be argued that the frequency with which those calculations are performed also should be accurate. Therefore a deviation from the guidelines is warranted. Reference this forum discussion [here](https://community.openhab.org/t/astro-binding-event-drift/44328)

vzorglub · May 2, 2018, 6:21am

Thank you, I know where now…

vzorglub · June 4, 2018, 6:55am

Fixed in the 2.3 release