samples/subsys/logging/logger timeout when sanitycheck enable coverage, it needs a filter

[wangnuannuan]

Describe the bug
When enable coverage, sanitycheck fails to get coverage data from samples/subsys/logging/logger.
The coverage data will be output by log_printk, because the CONFIG_LOG_PRINTK is enable, so the coverage data is treated as a log data.

zephyr/subsys/testsuite/coverage/coverage.c

Line 211 in ee525c2

printk("%c", GCOV_DUMP_SEPARATOR);

zephyr/lib/os/printk.c

Line 453 in 83b9f69

void printk(const char *fmt, ...)

[PerMac]

As a remark, I have no experience with the coverage usage, so what I am writing might have not much sense.
Edit: It didn't... I had no lcov installed so the comment was useless...

[wangnuannuan]

@PerMac For the other testcases, the program will dump coverage data by calling vprintk once the main() has exited. I have no idea how zephyr logger module work(Does it work in another thread that different from kernel's background thread?). But this testcase enable CONFIG_LOG_PRINTK, so it dumps coverage data by calling log_printk once the main() has exited.

It will take a long time to output all the coverage information, so the sanitycheck can't get the testcase state when timeout.

 /*  kernel/init.c */

	extern void main(void);

	main();

	/* Mark nonessenrial since main() has no more work to do */
	z_main_thread.base.user_options &= ~K_ESSENTIAL;

#ifdef CONFIG_COVERAGE_DUMP
	/* Dump coverage data once the main() has exited. */
	gcov_coverage_dump();
#endif
} 

 /* lib/os/printk.c */

void printk(const char *fmt, ...)
{
	va_list ap;
	va_start(ap, fmt);
	if (IS_ENABLED(CONFIG_LOG_PRINTK)) {
		log_printk(fmt, ap);
	} else {
		vprintk(fmt, ap);
	}
	va_end(ap);
}
#endif /* CONFIG_PRINTK */

[wangnuannuan]

@PerMac Is this a mistake? Here should be Gcovr(), right?

zephyr/scripts/sanity_chk/sanitylib.py

Line 3268 in 9df168b

t = Lcov()

class CoverageTool:
    """ Base class for every supported coverage tool
    """
    def __init__(self):
        self.gcov_tool = None
        self.base_dir = None

    @staticmethod
    def factory(tool):
        if tool == 'lcov':
            t =  Lcov()
        elif tool == 'gcovr':
            t =  Lcov()
        else:
            logger.error("Unsupported coverage tool specified: {}".format(tool))
            return None
        return t

[PerMac]

@wangnuannuan Yes: #27474

[PerMac]

@wangnuannuan I cannot reproduce the issue with the timeout on my PC. the code executes in time. However, I think there might be a different issue with --coverage. It looks like by default lcov is used, even when gcov data is collected. Can you try checking out at the #27474 (or maybe it will be already in the master by then) and running sanitycheck with extra --coverage --coverage-tool gcovr? When I run like this I am getting the reports. (Edit: I had no lcov installed)
As for the timeout, I guess we can add an option that when --coverage is used then the timeout is increased by X. However I would like to know how much extra time might be needed for coverage to finish. As I said, I don't see this issue. Could you check at your setup how much more time is needed? You can increase the timeout for the test in its yaml file by adding timeout option like below:

tests:
  sample.logger.basic:
    tags: logging
    timeout: 600
    harness: console

Then you can compare run times with and without --coverage

[wangnuannuan]

@PerMac I test it with west. Lcov or gcovr is not necessary here, because they are used to convert the coverage data (output by console) into HTML reports.

1. west build -b nsim_em ./zephyr/samples/subsys/logging/logger -- -DCONFIG_COVERAGE=y -DCONFIG_COVERAGE_DUMP=y
2. ninja run -Cbuild
   And following is the log:

$ ninja run -Cbuild
ninja: Entering directory `build'
[0/1] cd /SCRATCH/jingru/zephyr-project/build && /global/apps/arcnsim_2020.03/nSIM/bin/nsimdrv -propsfile /SCRATCH/jingru/zephyr-project/zephyr/boards/arc/nsim/support/nsim_em.props /SCRATCH/jingru/zephyr-project/build/zephyr/zephyr.elf
Console now belongs to UART, hit CRTL-] to return to simulator.
 00--- 9999 messages dropped ---
 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 c5 93 81 31 f0 9c 9f b4 b8 83 30 a4 00 00 a1 01 02 00 00 00 00 00 00 00 00 00 00 00
                                                                                                                                                                                       GCOV_COVERAGE_DUMP_END

        ---=< RUNNING LOGGER DEMO FROM KERNEL THREAD >=---

Module logging showcase.
[00:01:14.774,132] <inf> sample_module: log in test_module 11
[00:01:14.774,388] <inf> sample_module: Inline function.
Disabling logging in the sample_module module
...

The log information indicates that log_printk has analyzed and processed the Coverage data.

And following is the log of ./zephyr/samples/hello_world

ninja: Entering directory `build'
[0/1] cd /SCRATCH/jingru/zephyr-project/build && /global/apps/arcnsim_2020.03/nSIM/bin/nsimdrv -propsfile /SCRATCH/jingru/zephyr-project/zephyr/boards/arc/nsim/support/nsim_em.props /SCRATCH/jingru/zephyr-project/build/zephyr/zephyr.elf
Console now belongs to UART, hit CRTL-] to return to simulator.
*** Booting Zephyr OS build zephyr-v2.3.0-1212-gff3792b89c86  ***
Hello World! nsim

GCOV_COVERAGE_DUMP_START
*/SCRATCH/jingru/zephyr-project/build/zephyr/CMakeFiles/offsets.dir/arch/arc/core/offsets/offsets.c.gcda< 61 64 63 67 2a 32 39 41 b4 25 c1 dd 00 00 00 01 03 00 00 00 25 43 21 78 88 a5 01 03 7e 28 bb 2e 00 00 a1 01 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
*/SCRATCH/jingru/zephyr-project/build/zephyr/kernel/CMakeFiles/kernel.dir/kheap.c.gcda< 61 64 63 67 2a 32 39 41 0b 28 c1 dd 00 00 00 01 03 00 00 00 3d af e2 07 88 59 6f 9d 3e b2 bb c0 00 00 a1 01 04 00 00 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 95 81 38 3d 32 d1 36 6d 11 17 61 c8 00 00 a1 01 0a 00 00 00 02 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 3a 09 ff 30 bc 13 67 ed 36 9c 8e ad 00 00 a1 01 0e 00 00 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 59 0a cb 21 44 2b 5f d1 32 90 fb 08 00 00 a1 01 16 00 00 00 02 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 1c b4 e5 3b 23 51 2b 22 50 95 d1 93 00 00 a1 01 06 00 00 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 6f 50 11 33 35 0a bd c0 da 9c b4 f3 00 00 a1 01 06 00 00 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 30 4c 2f 47 a0 e8 7a 3d 3e b2 bb c0 00 00 a1 01 04 00 00 00 01 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 7f 8e 11 30 53 9d ad f7 3e b2 bb c0 00 00 a1 01 04 00 00 00 03 00 00 00 00 00 00 00 03 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 f9 7f 20 0d 04 50 eb 20 f9 4a b3 7c 00 00 a1 01 04 00 00 00 03 00 00 00 00 00 00 00 03 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 48 d9 68 65 3f 5f ad d3 3e b2 bb c0 00 00 a1 01 04 00 00 00 03 00 00 00 00 00 00 00 03 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 04 1a a4 14 f3 c4 69 5c f9 4a b3 7c 00 00 a1 01 04 00 00 00 03 00 00 00 00 00 00 00 03 00 00 00 00 00 00 00 00 00 00 01 03 00 00 00 37 be fe 6e 8c 16 b6 6d b8 83 30 a4 00 00 a1 01 02 00 00 00 01 00 00 00 00 00 00 00
...

[PerMac]

Do I need something extra installed to use ninja run -Cbuild for this nsim_em platform? I got an error when trying to reproduce. NSIM-NOTFOUND: not found. You have '/global/apps/arcnsim_2020.03/nSIM/bin/nsimdrv' in that place.
Anyhow, for me it looks like --coverage does not work with most of the platforms. I only managed to get the reports for native_posix. For others (e.g. qemu_x86) it looks like most of the information from coverage is skipped and only some last parts of it are added to the handler. This is what you also see in your output: 9999 messages dropped --- So there is no GCOV_COVERAGE_DUMP_START msg in the log, only GCOV_COVERAGE_DUMP_END and that is why coverage fails. I don't know what to do with this. @nashif I don't know if I can do anything else to help with this, can you take it over?

[wangnuannuan]

I think maybe the first thing to do is to make sure that only zephyr logger can call log_printk. Condition IS_ENABLED(CONFIG_LOG_PRINTK) is not enough.

void printk(const char *fmt, ...)
{
	va_list ap;

	va_start(ap, fmt);

	if (IS_ENABLED(CONFIG_LOG_PRINTK)) {
		log_printk(fmt, ap);
	} else {
		vprintk(fmt, ap);
	}
	va_end(ap);
}

[nashif]

This can be folded in #27573