tests: ztest: provide test execution times per ztest testcase #33014

enjiamai · 2021-03-06T17:12:30Z

Add execution time for testing result of each ztest testcase as:

START - test_sem_multi_take_timeout_diff_sem
PASS - test_sem_multi_take_timeout_diff_sem in 2.54 seconds

Signed-off-by: Enjia Mai enjiax.mai@intel.com

PerMac

I think the implementation doesn't bring exactly what was required in the feature. Currently, the printed time per test case is not the execution time of the test case but the time from the start of the whole test suite till the test case finishes. E.g check calling test from /tests/kernel/sleep. Test case test_usleep` shows that it took 2 seconds but in the calculated time it shows 4.420:

DEBUG   - DEVICE: *** Booting Zephyr OS build zephyr-v2.5.0-887-ga2c51c22e6d2  ***
DEBUG   - DEVICE: Running test suite sleep
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sleep
DEBUG   - DEVICE: Kernel objects initialized
DEBUG   - DEVICE: Test thread started: id = 0x20000138
DEBUG   - DEVICE: Helper thread started: id = 0x20000080
DEBUG   - DEVICE: Testing normal expiration of k_sleep()
DEBUG   - DEVICE: Testing: test thread sleep + helper thread wakeup test
DEBUG   - DEVICE: Testing: test thread sleep + isr offload wakeup test
DEBUG   - DEVICE: Testing: test thread sleep + main wakeup test thread
DEBUG   - DEVICE: Testing kernel k_sleep()
DEBUG   - DEVICE: PASS - test_sleep in 2.408 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_usleep
DEBUG   - DEVICE: elapsed_ms = 2000
DEBUG   - DEVICE: PASS - test_usleep in 4.420 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sleep_forever
DEBUG   - DEVICE: Kernel objects initialized
DEBUG   - DEVICE: PASS - test_sleep_forever in 4.435 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: Test suite sleep succeeded
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: PROJECT EXECUTION SUCCESSFUL
DEBUG   - run status: nrf52840dk_nrf52840/tests/kernel/sleep/kernel.common.timing passed
INFO    - 1/1 nrf52840dk_nrf52840       tests/kernel/sleep/kernel.common.timing            PASSED (device 10.441s)

What about deleting everything from get_start_time_cyc(void) and leaving there only

tc_start_time = k_cycle_get_32();

so that tc_start_time is always updated for each test case. Then maybe you can get rid off the already_started variable as it seems to be useless.
With the proposed changes I've got:

DEBUG   - DEVICE: *** Booting Zephyr OS build zephyr-v2.5.0-887-ga2c51c22e6d2  ***
DEBUG   - DEVICE: Running test suite sleep
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sleep
DEBUG   - DEVICE: Kernel objects initialized
DEBUG   - DEVICE: Test thread started: id = 0x20000138
DEBUG   - DEVICE: Helper thread started: id = 0x20000080
DEBUG   - DEVICE: Testing normal expiration of k_sleep()
DEBUG   - DEVICE: Testing: test thread sleep + helper thread wakeup test
DEBUG   - DEVICE: Testing: test thread sleep + isr offload wakeup test
DEBUG   - DEVICE: Testing: test thread sleep + main wakeup test thread
DEBUG   - DEVICE: Testing kernel k_sleep()
DEBUG   - DEVICE: PASS - test_sleep in 2.32 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_usleep
DEBUG   - DEVICE: elapsed_ms = 2000
DEBUG   - DEVICE: PASS - test_usleep in 2.2 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sleep_forever
DEBUG   - DEVICE: Kernel objects initialized
DEBUG   - DEVICE: PASS - test_sleep_forever in 0.3 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: Test suite sleep succeeded
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: PROJECT EXECUTION SUCCESSFUL
DEBUG   - run status: nrf52840dk_nrf52840/tests/kernel/sleep/kernel.common.timing passed
INFO    - 1/1 nrf52840dk_nrf52840       tests/kernel/sleep/kernel.common.timing            PASSED (device 10.148s)

PerMac · 2021-03-08T11:39:46Z

subsys/testsuite/include/tc_util.h

+	if (!IS_ENABLED(CONFIG_ZTEST) && already_started) {
+		tc_start_time = k_cycle_get_32();
+		already_started = true;


[please read the overall comment first. If the proposed solution doesn't make sense then consider this one] shouldn't it be ... && !already_started on the condition? If already_started is already true, why setting it again to true?

Yes, the logic for condition is wrong here, I shall correct it.

I remove the already_started here, thanks!

enjiamai · 2021-03-08T16:56:59Z

I think the implementation doesn't bring exactly what was required in the feature. Currently, the printed time per test case is not the execution time of the test case but the time from the start of the whole test suite till the test case finishes. E.g check calling test from /tests/kernel/sleep. Test case test_usleep` shows that it took 2 seconds but in the calculated time it shows 4.420:

I do appreciate your review, and understand what you concern is, let me explain it please:
Like you mentioned, indeed, the test execution time here includes some overhead of testsuite. My consideration here is:

The main goal of adding this is to understand roughly how much time each test case spends For example, we can take advantage of this to optimaized our testcase's cost. So from my point of view, the error of measurement can be ignored as long as they are all on the same basis. But test_usleep you mention is really not good here, I'll take a look into it.
Some current existing ZTEST testcases also call TC_START() in the their implementation, this make it was invoked twice, and make them not on the same measure basis. I don't want updated them per testcase( modified the from TC_START to TC_PRINT), so I add already_started to prevent from store the time again. But as your measurement in device testcase, it indeed will have some overhead.

Let me try if I can make this better, thank you so much for your example, it's so clear for me.

PerMac · 2021-03-09T09:20:31Z

the error of measurement can be ignored as long as they are all on the same basis

I agree :)

But as your measurement in device testcase, it indeed will have some overhead.

I believe it is because the start time is not updated for each test case and not due to the uncertainty of measurement. Like you wrote: "The main goal of adding this is to understand roughly how much time each test case spends". But now it shows from the beginning of the first test case, not the current one. That's why usleep case, which should last for ~2 sec shows ~4 secs (+ extra 2sec from previous one). You can see this playing with the test itself. Add to the line https://github.com/zephyrproject-rtos/zephyr/blob/master/tests/kernel/sleep/src/usleep.c#L54 *5 and see how this also affects the next test (test_sleep_forever) execution time.

I add already_started to prevent from store the time again

Without storing the start time for each test case you won't be able to calculate the run time for each individual test. You just need to update tc_start_time at the beginning of each test case.

nashif · 2021-03-09T12:02:07Z

I believe it is because the start time is not updated for each test case and not due to the uncertainty of measurement.

is it really like this? we call TC_START for each test and thats where it gets updated...

I have been using this patch in my branch, it shows the following:

      <testsuite name="fifo_api" time="0.981" tests="8" failures="0" errors="0" skipped="0">
        <properties>
          <property name="version" value="v2.5.0"/>
          <property name="platform" value="qemu_x86"/>
        </properties>
        <testcase classname="kernel.fifo" name="test_fifo_thread2thread" time="0.100"/>
        <testcase classname="kernel.fifo" name="test_fifo_thread2isr" time="0.100"/>
        <testcase classname="kernel.fifo" name="test_fifo_isr2thread" time="0.100"/>
        <testcase classname="kernel.fifo" name="test_fifo_get_fail" time="0.107"/>
        <testcase classname="kernel.fifo" name="test_fifo_loop" time="0.260"/>
        <testcase classname="kernel.fifo" name="test_fifo_cancel_wait" time="0.114"/>
        <testcase classname="kernel.fifo" name="test_fifo_is_empty_thread" time="0.100"/>
        <testcase classname="kernel.fifo" name="test_fifo_is_empty_isr" time="0.100"/>
      </testsuite>

PerMac · 2021-03-09T12:51:11Z

Now I am confused as I clearly see the issue as described above. Can you please check @nashif what would be the output of /tests/kernel/sleep in your case?

nashif · 2021-03-09T12:55:24Z

      <testsuite name="sleep" time="3.800" tests="3" failures="0" errors="0" skipped="0">
        <properties>
          <property name="version" value="zephyr-v2.5.0-549-g694aaf782f78"/>
          <property name="platform" value="qemu_cortex_m3"/>
        </properties>
        <testcase classname="kernel.common.timing" name="test_sleep" time="2.700"/>
        <testcase classname="kernel.common.timing" name="test_usleep" time="1.000"/>
        <testcase classname="kernel.common.timing" name="test_sleep_forever" time="0.100"/>
      </testsuite>
    </testsuites>

PerMac · 2021-03-09T13:23:27Z

I am confused... Your times look correct. This is what I get for qemu_cortex_m3

PASS - test_sleep in 2.71 seconds
PASS - test_usleep in 3.71 seconds
PASS - test_sleep_forever in 3.71 seconds

I am on Ubuntu 18.04, zephyr sdk 0.12.2 and being checked out on this PR's head: zephyr-v2.5.0-887-ga2c51c22e6d2

enjiamai · 2021-03-09T13:39:35Z

The result on twister_report.xml is correct, like @nashif show up, but in twister.log out put is incorrect, like @PerMac said. It seems like my code logic still has some problem need to be addressed. Thanks so much for both of your time on this , let me refine it first~

nashif · 2021-03-09T14:00:50Z

i have an old version of this PR in my branch, this could be the reason

PerMac · 2021-03-09T14:02:34Z

@nashif By the content of your xml, I would guess you calculate the difference between reported times in console, and if it is 0 you set it to 0.1. Does the output in the console show the same times as in the report?

nashif · 2021-03-09T14:04:08Z

@nashif By the content of your xml, I would guess you calculate the difference between reported times in console, and if it is 0 you set it to 0.1. Does the output in the console show the same times as in the report?

I capture the values as is and put them in the report, no calculation done. The only calculation is the total per testsuite.

nashif · 2021-03-09T14:05:12Z

I cherry picked the latest version of this PR, now I am getting:

      <testsuite name="sleep" time="10.130" tests="3" failures="0" errors="0" skipped="0">
        <properties>
          <property name="version" value="zephyr-v2.5.0-1001-g37406347c8b5"/>
          <property name="platform" value="qemu_cortex_m3"/>
        </properties>
        <testcase classname="kernel.common.timing" name="test_sleep" time="2.710"/>
        <testcase classname="kernel.common.timing" name="test_usleep" time="3.710"/>
        <testcase classname="kernel.common.timing" name="test_sleep_forever" time="3.710"/>
      </testsuite>

enjiamai · 2021-03-09T14:21:08Z

@nashif @PerMac Thank you for spending your time on this. I already catch the problem but there is another issue need to be solved to fit all the testcases , I'll update this soon.

enjiamai · 2021-03-10T10:04:11Z

@PerMac I think I have addressed the comments you mentioned before. I removed the already_start flag, but a check for whether the caller of TC_START macro is in userspace is needed. The test result of time is correct now. Could you please help to review it again, thanks!

PerMac · 2021-03-10T13:03:13Z

Thanks, @enjiamai, looks good now. C is not my domain, but the logic with the nice and extended description looks correct. I tested this patch on qemu (qemu_cortex_m3) and physical board (nrf5340dk_nrf5340_cpuapp) with the kernel/sleep test, playing with the time to sleep, ad the reported values are correct.
I just realized that including this without a corresponding patch fixing the name in the XML report would screw some external CI (e.g. mine ;) ) as testcase names inside XML reports will change for the ones with the execution time. @nashif, it looked like you have a commit for this? Maybe you can add it to this PR?
e.g.: <testcase classname="kernel.common" name="kernel.common.timing.sleep in 2.32 seconds" time="11.705680"/> where the name got screwed.

enjiamai · 2021-03-10T13:16:59Z

Yes, @PerMac , I think the xml report that Anas show us yesterday has already done some adaption in twister, so @nashif , could
you please let me know: Should I also keep updating this part or you already have a commit for it? Thank you!

nashif · 2021-03-10T19:39:04Z

you please let me know: Should I also keep updating this part or you already have a commit for it? Thank you!

this should be fixed as part of this PR

diff --git a/scripts/pylib/twister/harness.py b/scripts/pylib/twister/harness.py
index 2c30f9ab73..25bea110a3 100644
--- a/scripts/pylib/twister/harness.py
+++ b/scripts/pylib/twister/harness.py
@@ -2,7 +2,7 @@
 import re
 from collections import OrderedDict

-result_re = re.compile(".*(PASS|FAIL|SKIP) - (test_)?(.*)")
+result_re = re.compile(".*(PASS|FAIL|SKIP) - (test_)?(.*) in")

 class Harness:
     GCOV_START = "GCOV_COVERAGE_DUMP_START"

Add execution time for testing result of each ztest testcase as: START - test_sem_multi_take_timeout_diff_sem PASS - test_sem_multi_take_timeout_diff_sem in 2.54 seconds Fix zephyrproject-rtos#32137. Signed-off-by: Enjia Mai <enjiax.mai@intel.com>

enjiamai · 2021-03-11T14:09:29Z

@nashif @PerMac Thanks so much for your review and help on this PR!

enjiamai requested a review from nashif as a code owner March 6, 2021 17:12

github-actions bot added area: Test Framework Issues related not to a particular test, but to the framework instead area: Tests Issues related to a particular existing or missing test labels Mar 6, 2021

enjiamai requested review from LeiW000, pfl and chen-png March 6, 2021 17:13

enjiamai force-pushed the provide_exec_time_ztest branch 3 times, most recently from 01c55db to d047984 Compare March 7, 2021 14:41

enjiamai requested review from andyross and dcpleung as code owners March 7, 2021 14:41

github-actions bot added the area: Kernel label Mar 7, 2021

nashif requested a review from PerMac March 7, 2021 18:00

enjiamai force-pushed the provide_exec_time_ztest branch from d047984 to a2c51c2 Compare March 8, 2021 02:44

enjiamai removed request for andyross and dcpleung March 8, 2021 03:41

PerMac requested changes Mar 8, 2021

View reviewed changes

zephyrbot added the area: Testsuite Testsuite label Mar 8, 2021

zephyrbot assigned nashif Mar 8, 2021

enjiamai force-pushed the provide_exec_time_ztest branch 2 times, most recently from 1a7cda8 to 581ca9e Compare March 10, 2021 09:32

enjiamai force-pushed the provide_exec_time_ztest branch from 581ca9e to 3eb2c60 Compare March 11, 2021 05:20

github-actions bot added the area: Twister Twister label Mar 11, 2021

nashif approved these changes Mar 11, 2021

View reviewed changes

PerMac self-requested a review March 11, 2021 12:27

PerMac approved these changes Mar 11, 2021

View reviewed changes

nashif merged commit 2c5e2c2 into zephyrproject-rtos:master Mar 11, 2021

enjiamai deleted the provide_exec_time_ztest branch March 11, 2021 14:09

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tests: ztest: provide test execution times per ztest testcase #33014

tests: ztest: provide test execution times per ztest testcase #33014

enjiamai commented Mar 6, 2021

PerMac left a comment

PerMac Mar 8, 2021

enjiamai Mar 8, 2021

enjiamai Mar 10, 2021

enjiamai commented Mar 8, 2021

PerMac commented Mar 9, 2021

nashif commented Mar 9, 2021

PerMac commented Mar 9, 2021

nashif commented Mar 9, 2021

PerMac commented Mar 9, 2021

enjiamai commented Mar 9, 2021

nashif commented Mar 9, 2021

PerMac commented Mar 9, 2021

nashif commented Mar 9, 2021

nashif commented Mar 9, 2021

enjiamai commented Mar 9, 2021

enjiamai commented Mar 10, 2021

PerMac commented Mar 10, 2021 •

edited

Loading

enjiamai commented Mar 10, 2021

nashif commented Mar 10, 2021

enjiamai commented Mar 11, 2021

tests: ztest: provide test execution times per ztest testcase #33014

tests: ztest: provide test execution times per ztest testcase #33014

Conversation

enjiamai commented Mar 6, 2021

PerMac left a comment

Choose a reason for hiding this comment

PerMac Mar 8, 2021

Choose a reason for hiding this comment

enjiamai Mar 8, 2021

Choose a reason for hiding this comment

enjiamai Mar 10, 2021

Choose a reason for hiding this comment

enjiamai commented Mar 8, 2021

PerMac commented Mar 9, 2021

nashif commented Mar 9, 2021

PerMac commented Mar 9, 2021

nashif commented Mar 9, 2021

PerMac commented Mar 9, 2021

enjiamai commented Mar 9, 2021

nashif commented Mar 9, 2021

PerMac commented Mar 9, 2021

nashif commented Mar 9, 2021

nashif commented Mar 9, 2021

enjiamai commented Mar 9, 2021

enjiamai commented Mar 10, 2021

PerMac commented Mar 10, 2021 • edited Loading

enjiamai commented Mar 10, 2021

nashif commented Mar 10, 2021

enjiamai commented Mar 11, 2021

PerMac commented Mar 10, 2021 •

edited

Loading