Experimental Physics and
Industrial Control System

From: Tech-talk <tech-talk-bounces at aps.anl.gov> on behalf of Di Wang via Tech-talk <tech-talk at aps.anl.gov>
Date: Friday, July 7, 2023 at 1:44 AM
To: tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>
Subject: issue of getTimeStamp from EVR

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?  How to solve it? Or should I increase
the OS Clock priority to avoid calling getTimeStamp()?

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