Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

WIP: Add logging levels to ztest #1

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open

WIP: Add logging levels to ztest #1

wants to merge 1 commit into from

Conversation

tristan-google
Copy link
Owner

@tristan-google tristan-google commented Feb 5, 2022 •
edited
Loading

  • Define a set of ztest logging macros (ZTEST_ERR, ZTEST_WRN, etc)
  • Add a Kconfig (ZTEST_PRINT_TO_LOG) for choosing between routing
    the above to Zephyr logging framework (new) or built-in printk()
    logging (original)
  • Transistion ztest log outputs to these new macros at the appropriate
    levels.

TODO

  • Make sure the logging subsystem gets initialized properly. Does it
    need its own thread for processing? Maybe we need
    CONFIG_LOG_PROCESS_THREAD too?
  • There's a lot of test output happening in tc_util.h, which isn't
    part of ztest and has its own printk macro wrapper. Need to find
    a nice way to override that.
  • Zephyr logging adds a redundant newline
  • PROJECT EXECUTION SUCCESSFUL (or FAILED) message must always be printed
  • Various other TODOs and thoughts added in comments.

yperess
yperess reviewed Feb 9, 2022
View reviewed changes
Copy link
Collaborator

@yperess yperess left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wasn't able to run these for the test you selected (I don't have qemu installed I suppose or I'm not sure the exact command). I did try to add CONFIG_ZTEST_PRINT_TO_LOG=y to tests/ztest/base/prj_verbose_0.conf and it won't build.

The command is:

$ ./scripts/twister -v -p native_posix -s tests/ztest/base/testing.ztest.verbose_0

subsys/testsuite/ztest/include/ztest.h
#define ZTEST_PRINTK LOG_PRINTK
#else
/* Direct everything through printk */
#define ZTEST_DBG printk
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you remove the \n from the logs and do:

ZTEST_DBG(msg, ...) printk(msg "\n", ##__VA_ARGS__)

Copy link
Owner Author

@tristan-google tristan-google Feb 9, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was hoping to avoid this, as there are a lot of tests printing their own log messages, but if that's the best way forward I'll do that...

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You know, before we keep pushing on this we should know what the overhead of CONFIG_LOG=y is. There's an option to route logging to printk via CONFIG_LOG_PRINTK=y. It's possible that this is 100% acceptable and the overhead of requiring logging in ztest is fine.

yperess
yperess reviewed Feb 10, 2022
View reviewed changes
subsys/testsuite/ztest/include/ztest.h
/* Use the Zephyr logging subsystem */
#include <logging/log.h>

#ifndef ZTEST_DONT_DECLARE_LOG
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the convention is to prefix with Z_ for internal defines

subsys/testsuite/ztest/src/ztest.c
@@ -482,7 +482,7 @@ void ztest_verify_all_registered_test_suites_ran(void)

for (ptr = _ztest_suite_node_list_start; ptr < _ztest_suite_node_list_end; ++ptr) {
if (ptr->stats.run_count < 1) {
PRINT("ERROR: Test '%s' did not run.\n", ptr->name);
ZTEST_ERR("ERROR: Test '%s' did not run.\n", ptr->name);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I feel like these prefixes like ERROR: don't make sense anymore, can we remove them and add them in the printk case or remove them entirely

subsys/testsuite/ztest/include/ztest.h
#define ZTEST_PRINTK LOG_PRINTK
#else
/* Direct everything through printk */
#define ZTEST_DBG printk
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You know, before we keep pushing on this we should know what the overhead of CONFIG_LOG=y is. There's an option to route logging to printk via CONFIG_LOG_PRINTK=y. It's possible that this is 100% acceptable and the overhead of requiring logging in ztest is fine.

tests/arch/x86/static_idt/src/main.c Outdated
Comment on lines 13 to 18
#ifdef CONFIG_ZTEST_PRINT_TO_LOG
#include <logging/log.h>

LOG_MODULE_DECLARE(ztest_log_mod);
#endif /* CONFIG_ZTEST_PRINT_TO_LOG */

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I thought this was no longer needed

Copy link
Owner Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, will remove

@tristan-google
WIP: Add zephyr logging to ztest
63c596f 
This is a demo PR for the TSC based on a conversation on the #testing
channel in the Discord.

  * Define a set of ztest logging macros (ZTEST_ERR, ZTEST_WRN, etc)
    that get used globally.
  * Add a Kconfig for choosing between Zephyr logging framework and
    built-in printk() logging (only supported in new ztest API)
  * Transistion ztest log outputs to these new macros at the appropriate
    levels.

 ### TODO
  * There's a lot of test output happening in tc_util.h, which isn't
    part of ztest and has its own printk macro wrapper. Need to find
    a nice way to override that.
  * Various other TODOs and thoughts added in comments.
  * Strip newlines from log messages since logging subsystem adds its
    own.

Zephyr logging has been enabled in the `tests/ztest/base/` tests, which
you can run with `/workdir/zephyr/scripts/twister -T
/workdir/zephyr/tests/ztest/base -vvv` for dev purposes.
tristan-google pushed a commit that referenced this pull request Dec 7, 2022
@carlescufi @jhedberg
net: buf: Simplify fragment handling
3d306c1 
This patch reworks how fragments are handled in the net_buf
infrastructure.

In particular, it removes the union around the node and frags members in
the main net_buf structure. This is done so that both can be used at the
same time, at a cost of 4 bytes per net_buf instance.
This implies that the layout of net_buf instances changes whenever being
inserted into a queue (fifo or lifo) or a linked list (slist).

Until now, this is what happened when enqueueing a net_buf with frags in
a queue or linked list:

1.1 Before enqueueing:

 +--------+      +--------+      +--------+
 |#1  node|\     |#2  node|\     |#3  node|\
 |        | \    |        | \    |        | \
 | frags  |------| frags  |------| frags  |------NULL
 +--------+      +--------+      +--------+

net_buf #1 has 2 fragments, net_bufs #2 and #3. Both the node and frags
pointers (they are the same, since they are unioned) point to the next
fragment.

1.2 After enqueueing:

 +--------+      +--------+      +--------+      +--------+      +--------+
 |q/slist |------|#1  node|------|#2  node|------|#3  node|------|q/slist |
 |node    |      | *flag  | /    | *flag  | /    |        | /    |node    |
 |        |      | frags  |/     | frags  |/     | frags  |/     |        |
 +--------+      +--------+      +--------+      +--------+      +--------+

When enqueing a net_buf (in this case #1) that contains fragments, the
current net_buf implementation actually enqueues all the fragments (in
this case #2 and #3) as actual queue/slist items, since node and frags
are one and the same in memory. This makes the enqueuing operation
expensive and it makes it impossible to atomically dequeue. The `*flag`
notation here means that the `flags` member has been set to
`NET_BUF_FRAGS` in order to be able to reconstruct the frags pointers
when dequeuing.

After this patch, the layout changes considerably:

2.1 Before enqueueing:

 +--------+       +--------+       +--------+
 |#1  node|--NULL |#2  node|--NULL |#3  node|--NULL
 |        |       |        |       |        |
 | frags  |-------| frags  |-------| frags  |------NULL
 +--------+       +--------+       +--------+

This is very similar to 1.1, except that now node and frags are
different pointers, so node is just set to NULL.

2.2 After enqueueing:

 +--------+       +--------+       +--------+
 |q/slist |-------|#1  node|-------|q/slist |
 |node    |       |        |       |node    |
 |        |       | frags  |       |        |
 +--------+       +--------+       +--------+
                      |            +--------+       +--------+
                      |            |#2  node|--NULL |#3  node|--NULL
                      |            |        |       |        |
                      +------------| frags  |-------| frags  |------NULL
                                   +--------+       +--------+

When enqueuing net_buf #1, now we only enqueue that very item, instead
of enqueing the frags as well, since now node and frags are separate
pointers. This simplifies the operation and makes it atomic.

Resolves zephyrproject-rtos#52718.

Signed-off-by: Carles Cufi <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@yperess yperess yperess left review comments

Assignees
No one assigned
Labels
area: Test Framework
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@tristan-google @yperess