Re: Timing in seq record

[Michael Davidsaver via Tech-talk <tech-talk at aps.anl.gov>]

On 3/3/22 05:21, Mark Rivers via Tech-talk wrote:
> Hi Andrew,
>
> > Assuming that you’re seeing this on a Windows IOC I believe the fix for that was in  ...
>
> No, as my original message said I am seeing this on Linux (Centos 7).
>
> However, my statement that issue that Freddie referenced (106) is closed is incorrect.  That issue is still open.  That issue references several other issues that are closed, which is why I was confused.
>
> I believe Freddie is correct in his more recent message:
>
> > There were timers waking up early, but also half a quantum being subtracted from the time value asked for, I think to give a good average wakeup time for systems when wakeup is on boundaries of the quantum. I see that this subtraction still happens
>
> This looks like a problem of quantum/2 subtraction.

I agree that this arbitrary shortening is a ~bug, but it is worth remembering
that my attempt at removing this it caused a problem for you (Mark) on vxworks.

https://bugs.launchpad.net/epics-base/+bug/1861612/comments/12

There are some known problems with using epicsTimer for precise, short, delays.


> Mark
>
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> *From:* Johnson, Andrew N. <anj at anl.gov>
> *Sent:* Wednesday, March 2, 2022 10:17 PM
> *To:* Mark Rivers <rivers at cars.uchicago.edu>
> *Cc:* Freddie Akeroyd - STFC UKRI <freddie.akeroyd at stfc.ac.uk>; tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>
> *Subject:* Re: Timing in seq record
> Hi Mark,
>
> Assuming that you’re seeing this on a Windows IOC I believe the fix for that was in GitHub PR 131 https://github.com/epics-base/epics-base/pull/131 <https://github.com/epics-base/epics-base/pull/131> which was merged into the 3.15 branch (released in 3.15.9). The 3.15 branch was then merged into the 7.0 branch prior to the release of 7.0.6 last July.
>
> The release notes for it unfortunately don’t describe the problem very clearly or refer to the issue or pull request numbers, and because the fix came up from 3.15 they’re buried in the middle of the file, but they can be found in the 7.0 branch file at https://github.com/epics-base/epics-base/blob/7.0/documentation/RELEASE_NOTES.md#use-waitable-timers-on-microsoft-windows <https://github.com/epics-base/epics-base/blob/7.0/documentation/RELEASE_NOTES.md#use-waitable-timers-on-microsoft-windows>
>
> - Andrew
>
> --
> Complicity is easy, Simplexity takes real work
>
> > On Mar 2, 2022, at 8:37 PM, Mark Rivers via Tech-talk <tech-talk at aps.anl.gov> wrote:
> >
> > 
> > Hi Freddie,
> >
> > Thanks for pointing out that issue.
> >
> > That issue was closed on March 12, 2021, saying there has been a pull request.
> >
> > 7.0.6 was release on July 3, 2021, and 7.0.6.1 on October 6, 2021.  But I don't see anything about this issue in the release notes for either of these.
> >
> > Is there a release of base that fixes this fairly serious issue?
> >
> > Mark
> >
> > ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> > *From:* Freddie Akeroyd - STFC UKRI <freddie.akeroyd at stfc.ac.uk>
> > *Sent:* Wednesday, March 2, 2022 7:54 PM
> > *To:* Mark Rivers <rivers at cars.uchicago.edu>
> > *Subject:* RE: Timing in seq record
> >
> > Hi Mark,
> >
> > This might be related to Timers expire early · Issue #106 · epics-base/epics-base (github.com) <https://github.com/epics-base/epics-base/issues/106> as I think it may use timers for the delay
> >
> > Freddie
> >
> > *From:*Tech-talk <tech-talk-bounces at aps.anl.gov> *On Behalf Of *Mark Rivers via Tech-talk
> > *Sent:* 03 March 2022 00:35
> > *To:* Mark Rivers <rivers at cars.uchicago.edu>
> > *Cc:* tech-talk at aps.anl.gov
> > *Subject:* RE: Timing in seq record
> >
> > I see the same thing with base 7.0.5.
> >
> > *From:*Tech-talk <tech-talk-bounces at aps.anl.gov <mailto:tech-talk-bounces at aps.anl.gov>> *On Behalf Of *Mark Rivers via Tech-talk
> > *Sent:* Wednesday, March 2, 2022 6:31 PM
> > *To:* tech-talk at aps.anl.gov <mailto:tech-talk at aps.anl.gov>
> > *Subject:* Timing in seq record
> >
> > I have the following simple database with a seq record which just writes 1 and 0 to the Shutter record.  There is a delay of $(DELAY) before writing 1 and before writing 0.
> >
> > record(seq,"$(P)OpenCloseShutter") {
> >
> >     field(PINI, "YES")
> >
> >     field(DLY0,"$(DELAY)")
> >
> >     field(DOL0,"1")
> >
> >     field(LNK0,"$(P)Shutter PP MS")
> >
> >     field(DLY1,"$(DELAY)")
> >
> >     field(DOL1,"0")
> >
> >     field(LNK1,"$(P)Shutter PP MS")
> >
> >     field(FLNK,"$(P)OpenCloseShutter.PROC CA")
> >
> > }
> >
> > record(bo, "$(P)Shutter") {
> >
> >     field(ZNAM, "Done")
> >
> >     field(ONAM, "Moving")
> >
> > }
> >
> > If DELAY is 0.1 I see the following with camonitor on Shutter:
> >
> > Test:Shutter                   2022-03-02 18:22:24.997849 Moving
> >
> > Test:Shutter                   2022-03-02 18:22:25.092984 Done
> >
> > Test:Shutter                   2022-03-02 18:22:25.188102 Moving
> >
> > Test:Shutter                   2022-03-02 18:22:25.283205 Done
> >
> > Test:Shutter                   2022-03-02 18:22:25.378332 Moving
> >
> > Test:Shutter                   2022-03-02 18:22:25.473436 Done
> >
> > Test:Shutter                   2022-03-02 18:22:25.568547 Moving
> >
> > Test:Shutter                   2022-03-02 18:22:25.663681 Done
> >
> > Test:Shutter                   2022-03-02 18:22:25.758885 Moving
> >
> > Test:Shutter                   2022-03-02 18:22:25.854026 Done
> >
> > Test:Shutter                   2022-03-02 18:22:25.949228 Moving
> >
> > The period is about 190 ms rather than the expected 200 ms, but not too far off.
> >
> > However, if I set DELAY=0.01 then I see this:
> >
> > Test:Shutter                   2022-03-02 18:25:44.341923 Done
> >
> > Test:Shutter                   2022-03-02 18:25:44.347055 Moving
> >
> > Test:Shutter                   2022-03-02 18:25:44.352186 Done
> >
> > Test:Shutter                   2022-03-02 18:25:44.357367 Moving
> >
> > Test:Shutter                   2022-03-02 18:25:44.362523 Done
> >
> > Test:Shutter                   2022-03-02 18:25:44.367682 Moving
> >
> > Test:Shutter                   2022-03-02 18:25:44.372816 Done
> >
> > Test:Shutter                   2022-03-02 18:25:44.377965 Moving
> >
> > Test:Shutter                   2022-03-02 18:25:44.383104 Done
> >
> > Test:Shutter                   2022-03-02 18:25:44.388263 Moving
> >
> > Test:Shutter                   2022-03-02 18:25:44.393372 Done
> >
> > Test:Shutter                   2022-03-02 18:25:44.398496 Moving
> >
> > Test:Shutter                   2022-03-02 18:25:44.403633 Done
> >
> > The period is 10 ms when it should be 20 ms.  The DELAY appears to be 5 ms, not 10 ms.
> >
> > If I set DELAY=.005 then the Shutter PV has no monitor events.
> >
> > Something seems wrong here, since I know that epicsThreadSleep on Linux is capable of good accuracy down to 100 microseconds or so.
> >
> > This is base 7.0.4 on Centos 7.  Is this expected?
> >
> > Mark
> >
> > This email and any attachments are intended solely for the use of the named recipients. If you are not the intended recipient you must not use, disclose, copy or distribute this email or any of its attachments and should notify the sender immediately and delete this email from your system. UK Research and Innovation (UKRI) has taken every reasonable precaution to minimise risk of this email or any attachments containing viruses or malware but the recipient should carry out its own virus and malware checks before opening the attachments. UKRI does not accept any liability for any losses or damages which the recipient may sustain due to presence of any viruses.