| Message ID | 20250210-scanf-kunit-convert-v6-0-4d583d07f92d@gmail.com |
|---|---|
| Headers | show |
| Series | scanf: convert self-test to KUnit | expand |
On Tue 2025-02-11 06:45:07, Tamir Duberstein wrote: > On Tue, Feb 11, 2025 at 6:37 AM Petr Mladek <pmladek@suse.com> wrote: > > > > On Mon 2025-02-10 13:13:48, Tamir Duberstein wrote: > > > Convert the scanf() self-test to a KUnit test. > > > > > > In the interest of keeping the patch reasonably-sized this doesn't > > > refactor the tests into proper parameterized tests - it's all one big > > > test case. > > > > > > Acked-by: Petr Mladek <pmladek@suse.com> > > > > Please, remove this. The patchset has changed a lot and it is not > > longer true. > > Will do. > > > > > > --- a/lib/test_scanf.c > > > +++ b/lib/scanf_kunit.c > > > @@ -15,67 +13,49 @@ > > [...] > > > #define _check_numbers_template(arg_fmt, expect, str, fmt, n_args, ap) \ > > > do { \ > > > - pr_debug("\"%s\", \"%s\" ->\n", str, fmt); \ > > > + kunit_printk(KERN_DEBUG, test, "\"%s\", \"%s\" ->", str, fmt); \ > > > > The switch from pr_debug() to kunit_printk() causes printing huge > > amount of messages even when the test passes. > > I'm not able to reproduce this. It is because the loglevel filtering, see below. > pr_debug expands to printk(KERN_DEBUG, > ...) which is also what kunit_printk(KERN_DEBUG, ...) expands to. Can > you help me understand how you're testing? It is more complicated, see the following in include/linux/printk.h: <paste> /* If you are writing a driver, please use dev_dbg instead */ #if defined(CONFIG_DYNAMIC_DEBUG) || \ (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE)) #include <linux/dynamic_debug.h> /** * pr_debug - Print a debug-level message conditionally * @fmt: format string * @...: arguments for the format string * * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing. * * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses * pr_fmt() internally). */ #define pr_debug(fmt, ...) \ dynamic_pr_debug(fmt, ##__VA_ARGS__) #elif defined(DEBUG) #define pr_debug(fmt, ...) \ printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__) #else #define pr_debug(fmt, ...) \ no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__) #endif </paste> It would be nice to define it the other way around. But it would require reworking the macro trickery which might be tricky ;-) > > [ 5780.664377] KTAP version 1 > > [ 5780.664891] 1..1 > > [ 5780.665376] KTAP version 1 > > [ 5780.665765] # Subtest: scanf > > [ 5780.666104] # module: scanf_kunit > > [ 5780.666112] 1..10 > > [ 5780.667354] # numbers_simple: "0", "%llu" -> > > [ 5780.667371] # numbers_simple: 0 > > [ 5780.667923] # numbers_simple: "0", "%llu" -> > > [ 5780.668321] # numbers_simple: 0 > > [ 5780.668803] # numbers_simple: "1", "%llu" -> > > [ 5780.669175] # numbers_simple: 1 > > [ 5780.669624] # numbers_simple: "18446744073709551615", "%llu" -> > > > > [... skipping 7500+ lines ...] > > > > [ 5783.157777] # test_simple_strtol: simple_strtol("0x7fffffffffffffff", 0) -> 0x7fffffffffffffff > > [ 5783.158229] # test_simple_strtol: simple_strtol("0x8000000000000001", 0) -> 0x8000000000000001 > > [ 5783.158683] # test_simple_strtol: simple_strtol("0x8000000000000000", 0) -> 0x8000000000000000 > > [ 5783.159131] # test_simple_strtol: simple_strtol("0x8000000000000000", 0) -> 0x8000000000000000 > > [ 5783.159586] # test_simple_strtol: simple_strtol("0x8000000000000001", 0) -> 0x8000000000000001 > > [ 5783.160048] # test_simple_strtol: simple_strtol("0x7fffffffffffffff", 0) -> 0x7fffffffffffffff > > [ 5783.160506] # test_simple_strtol: simple_strtol("0xfffffffffffffffe", 0) -> 0xfffffffffffffffe > > [ 5783.160957] # test_simple_strtol: simple_strtol("0x2", 0) -> 0x2 > > [ 5783.161467] # test_simple_strtol: simple_strtol("0xffffffffffffffff", 0) -> 0xffffffffffffffff > > [ 5783.161806] # test_simple_strtol: simple_strtol("0x1", 0) -> 0x1 > > [ 5783.162564] ok 10 test_simple_strtol > > [ 5783.163145] # scanf: pass:10 fail:0 skip:0 total:10 > > [ 5783.163537] # Totals: pass:22 fail:0 skip:0 total:22 > > [ 5783.164052] ok 1 scanf I saw the above messages using "dmesg". They can also be seen in /sys/kernel/debug/kunit/scanf/results when CONFIG_KUNIT_DEBUGFS is enabled. > If you use one of the kunit userspace helpers, you will only see the > output when the test fails. Having said that, in my local testing I > don't see the KERN_DEBUG prints locally. I had to run with > ignore_loglevel to see them at all. Yeah, KERN_DEBUG are for the least important messages. Consoles usually do not print them to do not scare normal users and also historically because of slow serial consoles. Anyway, they are always stored into the internal log buffer. So that they can be seen by "dmesg" even when they were filtered on the console. BTW: The log buffer has a limited size. The oldest messages get lost when are too many of them. Which is another reason to do not print the debug messages by default. Best Regards, Petr PS: You are sending new revisions too fast. It is hard to follow. I personally prefer to send one revision per week at maximum. It gives people chance to find time for the review and provide some feedback.
On Tue, Feb 11, 2025 at 11:06 AM Petr Mladek <pmladek@suse.com> wrote: > > On Tue 2025-02-11 06:45:07, Tamir Duberstein wrote: > > On Tue, Feb 11, 2025 at 6:37 AM Petr Mladek <pmladek@suse.com> wrote: > > > > > > On Mon 2025-02-10 13:13:48, Tamir Duberstein wrote: > > > > Convert the scanf() self-test to a KUnit test. > > > > > > > > In the interest of keeping the patch reasonably-sized this doesn't > > > > refactor the tests into proper parameterized tests - it's all one big > > > > test case. > > > > > > > > Acked-by: Petr Mladek <pmladek@suse.com> > > > > > > Please, remove this. The patchset has changed a lot and it is not > > > longer true. > > > > Will do. > > > > > > > > > --- a/lib/test_scanf.c > > > > +++ b/lib/scanf_kunit.c > > > > @@ -15,67 +13,49 @@ > > > [...] > > > > #define _check_numbers_template(arg_fmt, expect, str, fmt, n_args, ap) \ > > > > do { \ > > > > - pr_debug("\"%s\", \"%s\" ->\n", str, fmt); \ > > > > + kunit_printk(KERN_DEBUG, test, "\"%s\", \"%s\" ->", str, fmt); \ > > > > > > The switch from pr_debug() to kunit_printk() causes printing huge > > > amount of messages even when the test passes. > > > > I'm not able to reproduce this. > > It is because the loglevel filtering, see below. > > > pr_debug expands to printk(KERN_DEBUG, > > ...) which is also what kunit_printk(KERN_DEBUG, ...) expands to. Can > > you help me understand how you're testing? > > It is more complicated, see the following in include/linux/printk.h: > > <paste> > /* If you are writing a driver, please use dev_dbg instead */ > #if defined(CONFIG_DYNAMIC_DEBUG) || \ > (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE)) > #include <linux/dynamic_debug.h> > > /** > * pr_debug - Print a debug-level message conditionally > * @fmt: format string > * @...: arguments for the format string > * > * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is > * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with > * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing. > * > * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses > * pr_fmt() internally). > */ > #define pr_debug(fmt, ...) \ > dynamic_pr_debug(fmt, ##__VA_ARGS__) > #elif defined(DEBUG) > #define pr_debug(fmt, ...) \ > printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__) > #else > #define pr_debug(fmt, ...) \ > no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__) > #endif > </paste> > > > It would be nice to define it the other way around. But it would > require reworking the macro trickery which might be tricky ;-) > > > > > [ 5780.664377] KTAP version 1 > > > [ 5780.664891] 1..1 > > > [ 5780.665376] KTAP version 1 > > > [ 5780.665765] # Subtest: scanf > > > [ 5780.666104] # module: scanf_kunit > > > [ 5780.666112] 1..10 > > > [ 5780.667354] # numbers_simple: "0", "%llu" -> > > > [ 5780.667371] # numbers_simple: 0 > > > [ 5780.667923] # numbers_simple: "0", "%llu" -> > > > [ 5780.668321] # numbers_simple: 0 > > > [ 5780.668803] # numbers_simple: "1", "%llu" -> > > > [ 5780.669175] # numbers_simple: 1 > > > [ 5780.669624] # numbers_simple: "18446744073709551615", "%llu" -> > > > > > > [... skipping 7500+ lines ...] > > > > > > [ 5783.157777] # test_simple_strtol: simple_strtol("0x7fffffffffffffff", 0) -> 0x7fffffffffffffff > > > [ 5783.158229] # test_simple_strtol: simple_strtol("0x8000000000000001", 0) -> 0x8000000000000001 > > > [ 5783.158683] # test_simple_strtol: simple_strtol("0x8000000000000000", 0) -> 0x8000000000000000 > > > [ 5783.159131] # test_simple_strtol: simple_strtol("0x8000000000000000", 0) -> 0x8000000000000000 > > > [ 5783.159586] # test_simple_strtol: simple_strtol("0x8000000000000001", 0) -> 0x8000000000000001 > > > [ 5783.160048] # test_simple_strtol: simple_strtol("0x7fffffffffffffff", 0) -> 0x7fffffffffffffff > > > [ 5783.160506] # test_simple_strtol: simple_strtol("0xfffffffffffffffe", 0) -> 0xfffffffffffffffe > > > [ 5783.160957] # test_simple_strtol: simple_strtol("0x2", 0) -> 0x2 > > > [ 5783.161467] # test_simple_strtol: simple_strtol("0xffffffffffffffff", 0) -> 0xffffffffffffffff > > > [ 5783.161806] # test_simple_strtol: simple_strtol("0x1", 0) -> 0x1 > > > [ 5783.162564] ok 10 test_simple_strtol > > > [ 5783.163145] # scanf: pass:10 fail:0 skip:0 total:10 > > > [ 5783.163537] # Totals: pass:22 fail:0 skip:0 total:22 > > > [ 5783.164052] ok 1 scanf > > I saw the above messages using "dmesg". > > They can also be seen in /sys/kernel/debug/kunit/scanf/results > when CONFIG_KUNIT_DEBUGFS is enabled. > > > > If you use one of the kunit userspace helpers, you will only see the > > output when the test fails. Having said that, in my local testing I > > don't see the KERN_DEBUG prints locally. I had to run with > > ignore_loglevel to see them at all. > > Yeah, KERN_DEBUG are for the least important messages. Consoles usually > do not print them to do not scare normal users and also historically > because of slow serial consoles. > > Anyway, they are always stored into the internal log buffer. So that > they can be seen by "dmesg" even when they were filtered on the > console. > > BTW: The log buffer has a limited size. The oldest messages get lost > when are too many of them. Which is another reason to do not > print the debug messages by default. > > > Best Regards, > Petr > > PS: You are sending new revisions too fast. It is hard to follow. > I personally prefer to send one revision per week at maximum. > It gives people chance to find time for the review and provide > some feedback. Thanks, I'll reduce the frequency. Apologies for the noise! I think all this is addressed in v7.
This is one of just 3 remaining "Test Module" kselftests (the others being bitmap and printf), the rest having been converted to KUnit. In addition to the enclosed patch, please consider this an RFC on the removal of the "Test Module" kselftest machinery. I tested this using: $ tools/testing/kunit/kunit.py run --arch arm64 --make_options LLVM=1 scanf Signed-off-by: Tamir Duberstein <tamird@gmail.com> --- Changes in v6: - s/at boot/at runtime/ for consistency with the printf series. - Go back to kmalloc. (Geert Uytterhoeven) - Link to v5: https://lore.kernel.org/r/20250210-scanf-kunit-convert-v5-0-8e64f3a7de99@gmail.com Changes in v5: - Remove extraneous trailing newlines from failure messages. - Replace `pr_debug` with `kunit_printk`. - Use static char arrays instead of kmalloc. - Drop KUnit boilerplate from CONFIG_SCANF_KUNIT_TEST help text. - Drop arch changes. - Link to v4: https://lore.kernel.org/r/20250207-scanf-kunit-convert-v4-0-a23e2afaede8@gmail.com Changes in v4: - Bake `test` into various macros, greatly reducing diff noise. - Revert control flow changes. - Link to v3: https://lore.kernel.org/r/20250204-scanf-kunit-convert-v3-0-386d7c3ee714@gmail.com Changes in v3: - Reduce diff noise in lib/Makefile. (Petr Mladek) - Split `scanf_test` into a few test cases. New output: : =================== scanf (10 subtests) ==================== : [PASSED] numbers_simple : ====================== numbers_list ======================= : [PASSED] delim=" " : [PASSED] delim=":" : [PASSED] delim="," : [PASSED] delim="-" : [PASSED] delim="/" : ================== [PASSED] numbers_list =================== : ============ numbers_list_field_width_typemax ============= : [PASSED] delim=" " : [PASSED] delim=":" : [PASSED] delim="," : [PASSED] delim="-" : [PASSED] delim="/" : ======== [PASSED] numbers_list_field_width_typemax ========= : =========== numbers_list_field_width_val_width ============ : [PASSED] delim=" " : [PASSED] delim=":" : [PASSED] delim="," : [PASSED] delim="-" : [PASSED] delim="/" : ======= [PASSED] numbers_list_field_width_val_width ======== : [PASSED] numbers_slice : [PASSED] numbers_prefix_overflow : [PASSED] test_simple_strtoull : [PASSED] test_simple_strtoll : [PASSED] test_simple_strtoul : [PASSED] test_simple_strtol : ====================== [PASSED] scanf ====================== : ============================================================ : Testing complete. Ran 22 tests: passed: 22 : Elapsed time: 5.517s total, 0.001s configuring, 5.440s building, 0.067s running - Link to v2: https://lore.kernel.org/r/20250203-scanf-kunit-convert-v2-1-277a618d804e@gmail.com Changes in v2: - Rename lib/{test_scanf.c => scanf_kunit.c}. (Andy Shevchenko) - Link to v1: https://lore.kernel.org/r/20250131-scanf-kunit-convert-v1-1-0976524f0eba@gmail.com --- Tamir Duberstein (2): scanf: convert self-test to KUnit scanf: break kunit into test cases MAINTAINERS | 2 +- lib/Kconfig.debug | 12 +- lib/Makefile | 2 +- lib/{test_scanf.c => scanf_kunit.c} | 274 +++++++++++++++++------------------ tools/testing/selftests/lib/Makefile | 2 +- tools/testing/selftests/lib/config | 1 - tools/testing/selftests/lib/scanf.sh | 4 - 7 files changed, 145 insertions(+), 152 deletions(-) --- base-commit: a64dcfb451e254085a7daee5fe51bf22959d52d3 change-id: 20250131-scanf-kunit-convert-f70dc33bb34c Best regards,