Experimental Physics and
Industrial Control System

Michael Davidsaver via Tech-talk <tech-talk at aps.anl.gov> · Fri, 7 Jul 2023 08:17:31 -0700

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
####################################

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System