Re: issue of getTimeStamp from EVR

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

On 7/6/23 23:44, Di Wang via Tech-talk wrote:
> Hi,
>
> I have a Linux IOC connecting to a PXIe chassis. The IOC is triggered by a PXI EVR at 50 Hz. About 300 records are processed every 20 ms. Sometimes the IOC misses the trigger.
>
> When I analyze the IOC overhead using `perf`, I find that the usage of getTimeStamp function from mrfioc2 is very high (see below). Then I use `perf annotate` to check getTimeStamp() and I find the CPU is waiting for below instructions. So I think the main reason is that the reading time from EVR takes too long.
>
> https://github.com/epics-modules/mrfioc2/blob/master/evrMrmApp/src/drvem.cpp#L801-L818
> // Get current absolute time
> epicsUInt32 ctrl=READ32(base, Control);
> // Latch timestamp
> WRITE32(base, Control, ctrl|Control_tsltch);
> ts.secPastEpoch=READ32(base, TSSecLatch);
> ts.nsec=READ32(base, TSEvtLatch);
> epicsUInt32 ctrl2=READ32(base, Control);
>
> As a General Time Provider, the EVR has the highest priority, it is nature that every record calls getTimeStamp() to read timestamp from EVR.
>
> Is such pciread latency normal?

Yes.


>   How to solve it? Or should I increase the OS Clock priority to avoid calling getTimeStamp()?

As you have found, an IOC calls getTimeStamp very frequently.
Firstly, you can add the following before iocInit()

> var mrmGTIFEnable 0
> ...
> iocInit()

This will prevent the EVR current time provider from being registered.
Note that the event time provider will always be registered.

In many cases, reliance on system time (via. NTP) can be entirely acceptable.
However, if a more precise wall clock time is desired, you could investigate
the  "NTPD Time Source" section.  This allows the system clock to be sync'd
through the EVR, which has much lower jitter than NTP.

https://epics.sourceforge.net/mrfioc2/evr-usage.pdf


> Cheers,
>
> Di WANG
> KEK
> ####################################
> epics> generalTimeReport
> Backwards time errors prevented 0 times.
>
> Current Time Providers:
>   "EVR", priority = 50
>    Current Time is 2023-07-06 19:28:39.738546.
>   "OS Clock", priority = 999
>    Current Time is 2023-07-06 19:28:39.738719.
>
> Event Time Providers:
>   "EVR", priority = 50
>
> # perf report
> overhead  Command          Shared Object          Symbol
>    45.26%  cbLow            libevrMrm.so.2.3       [.] EVRMRM::getTimeStamp
>    11.60%  CAS-event        libevrMrm.so.2.3       [.] EVRMRM::getTimeStamp
>     3.32%  cbHigh           libevrMrm.so.2.3       [.] mrmBufRx::drainbuf
>     2.26%  cbHigh           libevrMrm.so.2.3       [.] EVRMRM::getTimeStamp
>     1.85%  cbLow            libc.so.6              [.] __memmove_avx_unaligned_erms
>     1.76%  CAS-UDP          libevrMrm.so.2.3       [.] EVRMRM::getTimeStamp
>     1.28%  CAS-event        [kernel.kallsyms]      [k] syscall_return_via_sysret
>     1.00%  CAS-event        [kernel.kallsyms]      [k] entry_SYSCALL_64_after_hwframe
>
> Samples: 95K of event 'cycles', 4000 Hz, Event count (approx.): 84846615925
> EVRMRM::getTimeStamp /home/acc/epics/R3.15.9/modules/mrfioc2-2.3.0/lib/linux-x86_64/libevrMrm.so.2.3 [Percent: local period]
>    0.00 │    → callq EVRMRM::convertTS@plt
>    0.00 │      mov   %eax,%r13d
>         │      test  %al,%al
>         │    ↓ je    90
>    0.02 │      mov   0x8(%rsp),%rax
>    0.01 │      mov   %rax,(%r12)
>         │    ↓ jmp   93
>         │      nop
>         │90:   xor   %r13d,%r13d
>         │93:   mov   %r14,%rdi
>         │    → callq epicsMutex::unlock@plt
>    0.00 │      add   $0x10,%rsp
>         │      mov   %r13d,%eax
>    0.01 │      pop   %rbx
>    0.00 │      pop   %rbp
>    0.01 │      pop   %r12
>         │      pop   %r13
>         │      pop   %r14
>         │    ← retq
>         │      nop
>         │b0:   mov   0xe8(%rbp),%rax
>   24.10 │      mov   0x4(%rax),%ebx
>    0.04 │      mov   %ebx,%edx
>    0.00 │      or    $0x4,%dh
>    0.01 │      mov   %edx,0x4(%rax)
>   26.23 │      mov   0x68(%rax),%edx
>    0.08 │      mov   %edx,0x8(%rsp)
>   25.25 │      mov   0x6c(%rax),%edx
>    0.06 │      mov   %edx,0xc(%rsp)
>   24.03 │      mov   0x4(%rax),%edx
>    0.03 │      cmp   %ebx,%edx
> ####################################