Test time reported on tests using new ztest api on qemu_x86

[Laczen]

When running tests on qemu_x86 the time reported for a test to complete seems to report strange values. Tests that clearly take longer to execute report a run time that is smaller than for tests that take less time. Is there something that needs to be configured to get a correct estimation of the run time ?

[nashif]

Can you provide some example and the output with data please?

[Laczen]

@nashif , I noticed this while performing a test on an external module (https://github.com/Laczen/kvs/tree/main/zephyr). I guess there is no config option required. I will conduct some more tests and see if there is a bug somewhere.

[Laczen]

An example of a test with strange timings results:

/*
 * Copyright (c) 2012-2014 Wind River Systems, Inc.
 * SPDX-License-Identifier: Apache-2.0
 */

#include <string.h>
#include <zephyr/kernel.h>
#include <zephyr/ztest.h>

int ztest_sleep(void)
{
	return k_msleep(100);
}

ZTEST(ztest_timing, ztest_fast)
{
	int rc;

	for (int i = 0; i < 5; i++) {
		rc = ztest_sleep();
		zassert_equal(rc, 0, "ztest_sleep returned [%d]", rc);
	}
}

ZTEST(ztest_timing, ztest_slow)
{
	int rc;

	for (int i = 0; i < 50; i++) {
		rc = ztest_sleep();
		zassert_equal(rc, 0, "ztest_sleep returned [%d]", rc);
	}
}

ZTEST(ztest_timing, ztest_veryslow)
{
	int rc;

	for (int i = 0; i < 2000; i++) {
		rc = ztest_sleep();
		zassert_equal(rc, 0, "ztest_sleep returned [%d]", rc);
	}
}

ZTEST_SUITE(ztest_timing, NULL, NULL, NULL, NULL, NULL);

returns:

SeaBIOS (version zephyr-v1.0.0-0-g31d4e0e-dirty-20200714_234759-fv-az50-zephyr)
Booting from ROM..
*** Booting Zephyr OS build v3.4.0-rc3-88-g840eb576cc16 ***
Running TESTSUITE ztest_timing
===================================================================
START - ztest_fast
 PASS - ztest_fast in 0.546 seconds
===================================================================
START - ztest_slow
 PASS - ztest_slow in 5.500 seconds
===================================================================
START - ztest_veryslow
 PASS - ztest_veryslow in 5.251 seconds
===================================================================
TESTSUITE ztest_timing succeeded

------ TESTSUITE SUMMARY START ------

SUITE PASS - 100.00% [ztest_timing]: pass = 3, fail = 0, skip = 0, total = 3 duration = 11.297 seconds
 - PASS - [ztest_timing.ztest_fast] duration = 0.546 seconds
 - PASS - [ztest_timing.ztest_slow] duration = 5.500 seconds
 - PASS - [ztest_timing.ztest_veryslow] duration = 5.251 seconds

------ TESTSUITE SUMMARY END ------

===================================================================
PROJECT EXECUTION SUCCESSFUL