Experimental Physics and
Industrial Control System

Di Wang via Tech-talk <tech-talk at aps.anl.gov> · Fri, 7 Jul 2023 15:44:20 +0900

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

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System