Experimental Physics and
Industrial Control System

Timo Korhonen via Tech-talk <tech-talk at aps.anl.gov> · Fri, 7 Jul 2023 11:15:40 +0000

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