Experimental Physics and
Industrial Control System

Di Wang via Tech-talk <tech-talk at aps.anl.gov> · Fri, 7 Jul 2023 22:45:10 +0900

Hi Timo, Guobao,

Thanks very much for your comments.

As for my setup, I am using a commercial PC with AlmaLinux 9.2 installed

(kernel version is 5.14, RT kernel is enabled and tuned for high

throughput performance). The IOC also uses MCoreUtils module to set the

CPU affinity, schedule policy and priority.

For the hardware part, it uses NI PXIe-8381 to connect to the PXIe-1082

chassis. As you said, reading the timestamp from PCIe registers should

be very quick. So I suspect that the latency may be caused from the

PXIe-8381 module. I plan to measure it later.

For the usage of timestamp, actually I simply use it to diagnose the

processing order of records during early stage. For the final operation,

only one root record reading the EVR timestamp and other records inherit

the timestamp using TSEL should suffice.

Cheers,

Di WANG
KEK

On 7/7/2023 8:15 PM, Timo Korhonen wrote:

Hi,

I would like to see a few more details about your setup. In principle, reading the timestamp from PCIe registers should be very quick.
However, I am wondering if all of your 300 records really need an individual hardware timestamp, like your description seems to suggest.
I would imagine that you have a handful of events going on and you would like to know when those happened and timestamp your records with those times.

If you use the code to get the current absolute time, as it seems, you will in effect get a precise time when the software was processing your record.
I think that this is probably not what you actually want?

The other observation is that you appear to have a lot of records in the "cbLow" thread...that might also be worth to take a look. It could be the reason for the IOC missing triggers.

Based on how I interpret your case, I would suggest that you change timestamping to happen based on the events.
In addition, please consider if you can use TSEL to point to some "root" record that gets the timestamp from the event of interest.

My interpretation can of course be wrong and you indeed want to record the event processing times, or something in that direction. In that case, please let me know and we can take a new look.

I would not change the OS clock priority just yet.

Best regards,

Timo

On 2023-07-07, 08:44, "Tech-talk on behalf of Di Wang via Tech-talk" <tech-talk-bounces at aps.anl.gov <mailto:tech-talk-bounces at aps.anl.gov> on behalf of tech-talk at aps.anl.gov <mailto:tech-talk at aps.anl.gov>> 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 <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