benchmark.timing.userspace not working on nrf52840 with v1.13.0-rc1

[mbolivar]

To reproduce (on Linux; /dev/ttyACM0 varies by system):

$ git checkout v1.13.0-rc1
$ sanitycheck --device-testing --device-serial /dev/ttyACM0 -p nrf52840_pca10056 --test tests/benchmarks/timing_info/benchmark.timing.userspace
$ cat sanity-out/nrf52840_pca10056/tests/benchmarks/timing_info/benchmark.timing.userspace/handler.log

Expected results: test output includes measurements from userspace_bench() function in tests/benchmarks/timing_info/src/userspace_bench.c after mailbox measurements:

Actual output: userspace-specific test results are missing.

[mbolivar]

Complete contents of handler.log:

***** Booting Zephyr OS v1.13.0-rc1 *****
starting test - Time Measurement
Timing Results: Clock Frequency: 64 MHz
Context switch                               : 516 cycles ,  7998 ns
Interrupt latency                            :  92 cycles ,  1426 ns
Tick overhead                                : 300 cycles ,  4650 ns
Thread Creation                              : 876 cycles , 13578 ns
Thread cancel                                : 544 cycles ,  8432 ns
Thread abort                                 :1144 cycles , 17732 ns
Thread Suspend                               : 812 cycles , 12586 ns
Thread Resume                                : 768 cycles , 11904 ns
Thread Yield                                 : 708 cycles , 10974 ns
Thread Sleep                                 : 996 cycles , 15438 ns
Heap Malloc                                  : 704 cycles , 10912 ns
Heap Free                                    : 648 cycles , 10044 ns
Semaphore Take with context switch           :1068 cycles , 16554 ns
Semaphore Give with context switch           : 928 cycles , 14384 ns
Semaphore Take without context switch        :  76 cycles ,  1178 ns
Semaphore Give without context switch        : 200 cycles ,  3100 ns
Mutex lock                                   : 180 cycles ,  2790 ns
Mutex unlock                                 : 224 cycles ,  3472 ns
Message Queue Put with context switch        :1028 cycles , 15934 ns
Message Queue Put without context switch     : 260 cycles ,  4030 ns
Message Queue get with context switch        :1096 cycles , 16988 ns
Message Queue get without context switch     : 256 cycles ,  3968 ns
MailBox synchronous put                      :1148 cycles , 17794 ns
MailBox synchronous get                      :1132 cycles , 17546 ns
MailBox asynchronous put                     : 348 cycles ,  5394 ns
MailBox get without context switch           : 624 cycles ,  9672 ns
Timing Measurement  finished
PASS - main

Results when run with sanitycheck -p qemu_x86 for comparison:

[some output skipped]

MailBox get without context switch           :234411 cycles , 2344110 ns
Drop to user mode                            :927492 cycles , 9274920 ns
User thread Creation                         :93641 cycles , 936410 ns
Syscall overhead                             :45661 cycles , 456610 ns
Validation overhead k object init            :115563 cycles , 1155630 ns
Validation overhead k object permission      :64293 cycles , 642930 ns
Timing Measurement  finished
PASS - main

[mbolivar]

Results when run on nrf52840_pca10056 with PRINT_ALL_MEASUREMENTS defined in timing_info.h:

[snip]

MailBox get without context switch           : 636 cycles ,  9858 ns
Drop to user mode                            :597116 cycles , 9255298 ns
User thread Creation                         :   0 cycles ,     0 ns
Syscall overhead                             :   0 cycles ,     0 ns
Validation overhead k object init            :   0 cycles ,     0 ns
Validation overhead k object permission      :   0 cycles ,     0 ns
Timing Measurement  finished
PASS - main

Seems the results are being filtered out as invalid?

[nashif]

works fine on frdm_k64f

[mbolivar]

works fine on frdm_k64f

It's working for me on frdm_k64f as well.

I don't understand this code very well, but would it more sense to fail the test rather than filter out "bad" or missing results with PRINT_ALL_MEASUREMENTS? Failing platforms could then be blacklisted so they stick out more in the YAML file, instead of having to look through handler.log by hand.

[nashif]

something wrong with the timer and how we capture time in the benchmark, I am going to lower priority, because this is just a test issue, not in userspace and not in the timer itself.