Does it make sense latency_measure on M4 (imx8mm) is taking 3909547 cycles, 9773869ns for stack.push.wake+ctx.k_tok

[hutchman]

Hi,

Fairly new to Zephyr but running some benchmark tests on various platforms and was wondering if some of the big numbers I'm seeing on a NXP imx8mm-evk M4 are normal or not. Below is typically what I'm seeing when I run latency_measure.

Thanks,

Brian

*** Booting Zephyr OS build v4.1.0-3878-gfbdf4b9c64f6 ***
thread.yield.preemptive.ctx.k_to_k       - Context switch via k_yield                         :     203 cycles ,      509 ns : 
thread.yield.cooperative.ctx.k_to_k      - Context switch via k_yield                         :     203 cycles ,      509 ns : 
isr.resume.interrupted.thread.kernel     - Return from ISR to interrupted thread              :     190 cycles ,      477 ns : 
isr.resume.different.thread.kernel       - Return from ISR to another thread                  :     240 cycles ,      602 ns : 
thread.create.kernel.from.kernel         - Create thread                                      :     251 cycles ,      629 ns : 
thread.start.kernel.from.kernel          - Start thread                                       :     316 cycles ,      792 ns : 
thread.suspend.kernel.from.kernel        - Suspend thread                                     :     186 cycles ,      467 ns : 
thread.resume.kernel.from.kernel         - Resume thread                                      :     232 cycles ,      582 ns : 
thread.abort.kernel.from.kernel          - Abort thread                                       :     181 cycles ,      454 ns : 
fifo.put.immediate.kernel                - Add data to FIFO (no ctx switch)                   :     111 cycles ,      279 ns : 
fifo.get.immediate.kernel                - Get data from FIFO (no ctx switch)                 :      93 cycles ,      234 ns : 
fifo.put.alloc.immediate.kernel          - Allocate to add data to FIFO (no ctx switch)       :     556 cycles ,     1390 ns : 
fifo.get.free.immediate.kernel           - Free when getting data from FIFO (no ctx switch)   :     496 cycles ,     1240 ns : 
fifo.get.blocking.k_to_k                 - Get data from FIFO (w/ ctx switch)                 :     418 cycles ,     1047 ns : 
fifo.put.wake+ctx.k_to_k                 - Add data to FIFO (w/ ctx switch)                   :     480 cycles ,     1200 ns : 
fifo.get.free.blocking.k_to_k            - Free when getting data from FIFO (w/ ctx switch)   :     420 cycles ,     1050 ns : 
fifo.put.alloc.wake+ctx.k_to_k           - Allocate to add data to FIFO (w/ ctx switch)       :     479 cycles ,     1197 ns : 
lifo.put.immediate.kernel                - Add data to LIFO (no ctx switch)                   :     110 cycles ,      277 ns : 
lifo.get.immediate.kernel                - Get data from LIFO (no ctx switch)                 :      93 cycles ,      234 ns : 
lifo.put.alloc.immediate.kernel          - Allocate to add data to LIFO (no ctx switch)       :     556 cycles ,     1390 ns : 
lifo.get.free.immediate.kernel           - Free when getting data from LIFO (no ctx switch)   :     496 cycles ,     1240 ns : 
lifo.get.blocking.k_to_k                 - Get data from LIFO (w/ ctx switch)                 :     418 cycles ,     1047 ns : 
lifo.put.wake+ctx.k_to_k                 - Add data to LIFO (w/ ctx switch)                   :     479 cycles ,     1197 ns : 
lifo.get.free.blocking.k_to_k            - Free when getting data from LIFO (w/ ctx switch)   :     420 cycles ,     1050 ns : 
lifo.put.alloc.wake+ctx.k_to_k           - Allocate to add data to LIFO (w/ ctx switch)       :     479 cycles ,     1197 ns : 
events.post.immediate.kernel             - Post events (nothing wakes)                        :     159 cycles ,      397 ns : 
events.set.immediate.kernel              - Set events (nothing wakes)                         :     159 cycles ,      397 ns : 
events.wait.immediate.kernel             - Wait for any events (no ctx switch)                :     104 cycles ,      260 ns : 
events.wait_all.immediate.kernel         - Wait for all events (no ctx switch)                :     103 cycles ,      257 ns : 
events.wait.blocking.k_to_k              - Wait for any events (w/ ctx switch)                :     361 cycles ,      904 ns : 
events.set.wake+ctx.k_to_k               - Set events (w/ ctx switch)                         :     526 cycles ,     1317 ns : 
events.wait_all.blocking.k_to_k          - Wait for all events (w/ ctx switch)                :     455 cycles ,     1137 ns : 
events.post.wake+ctx.k_to_k              - Post events (w/ ctx switch)                        :     613 cycles ,     1532 ns : 
semaphore.give.immediate.kernel          - Give a semaphore (no waiters)                      :      59 cycles ,      147 ns : 
semaphore.take.immediate.kernel          - Take a semaphore (no blocking)                     :      69 cycles ,      172 ns : 
semaphore.take.blocking.k_to_k           - Take a semaphore (context switch)                  :     313 cycles ,      784 ns : 
semaphore.give.wake+ctx.k_to_k           - Give a semaphore (context switch)                  : 3909438 cycles ,  9773596 ns : 
condvar.wait.blocking.k_to_k             - Wait for a condvar (context switch)                : 3892799 cycles ,  9731997 ns : 
condvar.signal.wake+ctx.k_to_k           - Signal a condvar (context switch)                  :   17291 cycles ,    43228 ns : 
stack.push.immediate.kernel              - Add data to k_stack (no ctx switch)                :      68 cycles ,      172 ns : 
stack.pop.immediate.kernel               - Get data from k_stack (no ctx switch)              :      72 cycles ,      182 ns : 
stack.pop.blocking.k_to_k                - Get data from k_stack (w/ ctx switch)              :     411 cycles ,     1029 ns : 
stack.push.wake+ctx.k_to_k               - Add data to k_stack (w/ ctx switch)                : 3909547 cycles ,  9773869 ns : 
mutex.lock.immediate.recursive.kernel    - Lock a mutex                                       :      83 cycles ,      207 ns : 
mutex.unlock.immediate.recursive.kernel  - Unlock a mutex                                     :      44 cycles ,      110 ns : 
heap.malloc.immediate                    - Average time for heap malloc                       :     403 cycles ,     1007 ns : 
heap.free.immediate                      - Average time for heap free                         :     400 cycles ,     1000 ns : 
===================================================================
PROJECT EXECUTION SUCCESSFUL

[ldomaigne]

Some of the tests involve a context switch.

For instance, the mentioned test stack.push.wake+ctx.k_to_k create a kernel stack object and two kernel threads. This stack object is implemented using a LIFO queue:

• thread 1: pop() the value from the (empty) stack , with a timeout of K_FOREVER. Since the stack is empty, it blocks.
• thread 2: push() the value to the stack. This wakes thread 1, and a context switch occurs because thread 1's priority is higher.
• thread 1: pop() returns and finishes processing, causing a context switch.
• thread 2: push() returns. time measured = push + wake + ctx switch.

However taking about 1ms look suspicious to me. It is as if something else run during the benchmarking?

[hutchman]

Hi,

Nothing else going on, only this test.

I stopped in u-boot and did:

ext4load mmc 1:2 0x48000000 /root/m4/latency_measure.bin
cp.b 0x48000000 0x7e0000 20000
bootaux 0x7e0000

9773869ns is 9.77ms so don't know which 1ms you are referring to.

Regards,

Brian

[ldomaigne]

9773869ns is 9.77ms so don't know which 1ms you are referring to.

Yeah, looks like I'm off by an order of magnitude 🤣 I meant 10ms, not 1ms.
It looks even more suspicious (x10 more).

@DerekSnell , any ideas?

[hutchman]

I did this same test on an earlier version of Zephyr (and ran it on the A core too but those results looked fine) and it was even worse ( more areas with big numbers) so I don't quite know what to make of it. Here are those results (sorry, it's copied from an email and the formatting got messed up):

*** Booting Zephyr OS build v4.0.0-4569-g8cff70a95d6c ***
thread.yield.preemptive.ctx.k_to_k       - Context switch via k_yield
                       :     206 cycles ,      517 ns :
thread.yield.cooperative.ctx.k_to_k      - Context switch via k_yield
                       :     206 cycles ,      517 ns :
isr.resume.interrupted.thread.kernel     - Return from ISR to
interrupted thread              :     190 cycles ,      477 ns :
isr.resume.different.thread.kernel       - Return from ISR to another
thread                  :     243 cycles ,      609 ns :
thread.create.kernel.from.kernel         - Create thread
                       :     251 cycles ,      629 ns :
thread.start.kernel.from.kernel          - Start thread
                       :     319 cycles ,      799 ns :
thread.suspend.kernel.from.kernel        - Suspend thread
                       :     188 cycles ,      472 ns :
thread.resume.kernel.from.kernel         - Resume thread
                       :     235 cycles ,      589 ns :
thread.abort.kernel.from.kernel          - Abort thread
                       : 3909266 cycles ,  9773166 ns :
fifo.put.immediate.kernel                - Add data to FIFO (no ctx
switch)                   :     112 cycles ,      282 ns :
fifo.get.immediate.kernel                - Get data from FIFO (no ctx
switch)                 :      93 cycles ,      234 ns :
fifo.put.alloc.immediate.kernel          - Allocate to add data to
FIFO (no ctx switch)       :     663 cycles ,     1657 ns :
fifo.get.free.immediate.kernel           - Free when getting data from
FIFO (no ctx switch)   :     495 cycles ,     1237 ns :
fifo.get.blocking.k_to_k                 - Get data from FIFO (w/ ctx
switch)                 :     412 cycles ,     1032 ns :
fifo.put.wake+ctx.k_to_k                 - Add data to FIFO (w/ ctx
switch)                   :     482 cycles ,     1205 ns :
fifo.get.free.blocking.k_to_k            - Free when getting data from
FIFO (w/ ctx siwtch)   :     414 cycles ,     1035 ns :
fifo.put.alloc.wake+ctx.k_to_k           - Allocate to add data to
FIFO (w/ ctx switch)       :     481 cycles ,     1202 ns :
lifo.put.immediate.kernel                - Add data to LIFO (no ctx
switch)                   :     111 cycles ,      279 ns :
lifo.get.immediate.kernel                - Get data from LIFO (no ctx
switch)                 :      93 cycles ,      234 ns :
lifo.put.alloc.immediate.kernel          - Allocate to add data to
LIFO (no ctx switch)       :     663 cycles ,     1657 ns :
lifo.get.free.immediate.kernel           - Free when getting data from
LIFO (no ctx switch)   : 3909586 cycles ,  9773966 ns :
lifo.get.blocking.k_to_k                 - Get data from LIFO (w/ ctx
switch)                 :     412 cycles ,     1032 ns :
lifo.put.wake+ctx.k_to_k                 - Add data to LIFO (w/ ctx
switch)                   :     481 cycles ,     1202 ns :
lifo.get.free.blocking.k_to_k            - Free when getting data from
LIFO (w/ ctx switch)   : 3909505 cycles ,  9773764 ns :
lifo.put.alloc.wake+ctx.k_to_k           - Allocate to add data to
LIFO (w/ ctx siwtch)       :     481 cycles ,     1202 ns :
events.post.immediate.kernel             - Post events (nothing wakes)
                       :     159 cycles ,      397 ns :
events.set.immediate.kernel              - Set events (nothing wakes)
                       :     158 cycles ,      395 ns :
events.wait.immediate.kernel             - Wait for any events (no ctx
switch)                :     103 cycles ,      257 ns :
events.wait_all.immediate.kernel         - Wait for all events (no ctx
switch)                :     103 cycles ,      257 ns :
events.wait.blocking.k_to_k              - Wait for any events (w/ ctx
switch)                :     355 cycles ,      889 ns :
events.set.wake+ctx.k_to_k               - Set events (w/ ctx switch)
                       :     528 cycles ,     1322 ns :
events.wait_all.blocking.k_to_k          - Wait for all events (w/ ctx
switch)                :     450 cycles ,     1125 ns :
events.post.wake+ctx.k_to_k              - Post events (w/ ctx switch)
                       :     615 cycles ,     1537 ns :
semaphore.give.immediate.kernel          - Give a semaphore (no
waiters)                      :      59 cycles ,      147 ns :
semaphore.take.immediate.kernel          - Take a semaphore (no
blocking)                     :      69 cycles ,      172 ns :
semaphore.take.blocking.k_to_k           - Take a semaphore (context
switch)                  :     308 cycles ,      772 ns :
semaphore.give.wake+ctx.k_to_k           - Give a semaphore (context
switch)                  :     349 cycles ,      874 ns :
condvar.wait.blocking.k_to_k             - Wait for a condvar (context
switch)                :     479 cycles ,     1197 ns :
condvar.signal.wake+ctx.k_to_k           - Signal a condvar (context
switch)                  : 3909606 cycles ,  9774016 ns :
stack.push.immediate.kernel              - Add data to k_stack (no ctx
switch)                :      67 cycles ,      169 ns :
stack.pop.immediate.kernel               - Get data from k_stack (no
ctx switch)              :      72 cycles ,      182 ns :
stack.pop.blocking.k_to_k                - Get data from k_stack (w/
ctx switch)              :     405 cycles ,     1014 ns :
stack.push.wake+ctx.k_to_k               - Add data to k_stack (w/ ctx
switch)                : 3909547 cycles ,  9773869 ns :
mutex.lock.immediate.recursive.kernel    - Lock a mutex
                       :      83 cycles ,      207 ns :
mutex.unlock.immediate.recursive.kernel  - Unlock a mutex
                       :      44 cycles ,      110 ns :
heap.malloc.immediate                    - Average time for heap
malloc                       :     523 cycles ,     1307 ns :
heap.free.immediate                      - Average time for heap free
                       :     399 cycles ,      997 ns :
===================================================================
PROJECT EXECUTION SUCCESSFUL