Skip to content

py/mpprint.h: Add MP_DEBUG_PRINT() macro and MP_DEBUG_PRINT_LEVEL. #8050

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.

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

Closed
wants to merge 4 commits into from

Conversation

IhorNehrutsa
Copy link
Contributor

@IhorNehrutsa IhorNehrutsa commented Nov 30, 2021

Debugging macro for developers.

How to use:

// Important! Set MP_DEBUG_PRINT_LEVEL in *.c or *.cpp development file BEFORE any "MicroPython's *.h" includes.
// For example:
#define MP_DEBUG_PRINT_LEVEL MP_DEBUG_PRINT_TRACE // show all messages
// Include mpprint.h after defining the MP_DEBUG_PRINT_LEVEL
#include "py/mpprint.h"
...
#include "py/obj.h"
#include "py/runtime.h"
...
// Add MP_DEBUG_PRINT() macro in code, like
void foo(int arg) {
    MP_DEBUG_PRINT(MP_DEBUG_PRINT_TRACE, "Enter foo()")
    if (arg < 0) {
        MP_DEBUG_PRINT(MP_DEBUG_PRINT_WARNING, "arg=%d less zero", arg)
        ...
    }
    ...
    int value;
    ...
    // calculate value
    ...
    MP_DEBUG_PRINT(MP_DEBUG_PRINT_INFO, "See a value=%d", value)
    ...
    MP_DEBUG_PRINT(MP_DEBUG_PRINT_TRACE, "Exit foo()")
}

// It is not a dogma. You may start debugging from level 30.
#define MP_DEBUG_PRINT_LEVEL 30
// Then add MP_DEBUG_PRINT(30, ...) and when gets too many messages then change some messages to the next level MP_DEBUG_PRINT(40, ...), or MP_DEBUG_PRINT(20, ...) etc.
// Then you may change MP_DEBUG_PRINT_LEVEL to 20(reduce printing), and finally to 0(suppress printing).

// Usually, you will debug one or two source files. Debug printing from other files is suppressed if MP_DEBUG_PRINT_LEVEL is 0 or undefined.

py/mpprint.h Outdated
// 4 - DEBUG, more detaled info, dig deeper
// 5 - TRACE, show algorithm flow
// In real you may use own classification of debug levels.
#define DBG(level, ...) \
Copy link
Contributor

@stinos stinos Nov 30, 2021

Choose a reason for hiding this comment

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

Should be guarded by #ifndef DBG because this is a super common name and people might want to change what it does, disable it, etc

Copy link
Contributor Author

@IhorNehrutsa IhorNehrutsa Nov 30, 2021

Choose a reason for hiding this comment

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

It may be PRN() & PRN_LEVEL
or MSG() & MSG_LEVEL

Copy link
Contributor

Choose a reason for hiding this comment

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

That's still fairly common. Could prefix it with mp_. Still should be a no-op by default I guess, as are all other macros like this (DEBUG_printf etc)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Both pair (PRN() & PRN_LEVEL) and (MSG() & MSG_LEVEL) not used in MicroPython.

There is

#define debug(lvl, x...) do { if (lvl <= DEBUG_LEVEL) { printf(x); } } while (0)

at https://github.com/atgreen/libffi/blob/e9de7e35f2339598b16cbb375f9992643ed81209/src/pa/ffi.c#L52

Copy link
Contributor

Choose a reason for hiding this comment

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

Both pair (PRN() & PRN_LEVEL) and (MSG() & MSG_LEVEL) not used in MicroPython.

Indeed, but mpprint.h is part of the public API so any definitions it in might clash with external software. So if someone includes mpprint.h, in that same file it would not be possible to also include another file which has MSG defined (unless working around it)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Changed to PM_PRN() & PM_PRN_LEVEL

@codecov-commenter
Copy link

codecov-commenter commented Dec 2, 2021

Codecov Report

Merging #8050 (e2acba6) into master (5232847) will not change coverage.
The diff coverage is n/a.

@@           Coverage Diff           @@
##           master    #8050   +/-   ##
=======================================
  Coverage   98.39%   98.39%           
=======================================
  Files         158      158           
  Lines       20939    20939           
=======================================
  Hits        20602    20602           
  Misses        337      337           

@IhorNehrutsa IhorNehrutsa changed the title py/mpprint.h: Add DBG() macro. py/mpprint.h: Add MP_PRN() macro and MP_PRN_LEVEL. Dec 9, 2021
@IhorNehrutsa
Copy link
Contributor Author

@dpgeorge
Could you please review this PR?
Thanks for your work.

@IhorNehrutsa
Copy link
Contributor Author

Tested in PR esp32\machine_pwm.c: HOTFIX PWM duty #8075

@dpgeorge dpgeorge added the py-core Relates to py/ directory in source label Jan 21, 2022
@iabdalkader
Copy link
Contributor

iabdalkader commented Jan 24, 2022

This has been on my mind for a while because I noticed debug_printf is defined multiple times in multiple files (especially in ports and extmod) as DEBUG_printf or debug_printf. It would be nice if all instances of that macro are removed and replaced with a common standard debug macro. It would also be nice if the log levels for that macro are symbolic (ex: MP_LOG_DEBUG, MP_LOG_DRIVER, MP_LOG_ERROR, MP_LOG_MESSAGE and so on)... Also DEBUG_PRINT block below is duplicated in all py/*. This can be removed too and replaced with the common macro using the lowest debugging level or a level that's defined in every file. Note, you can look at printk levels for ideas.

#if MICROPY_DEBUG_VERBOSE // print debugging info
#define DEBUG_PRINT (1)
#define DEBUG_printf DEBUG_printf
#else // don't print debugging info
#define DEBUG_PRINT (0)
#define DEBUG_printf(...) (void)0
#endif

@github-actions
Copy link

github-actions bot commented Mar 9, 2023

Code size report:

   bare-arm:    +0 +0.000% 
minimal x86:    +0 +0.000% 
   unix x64:    +0 +0.000% standard
      stm32:    +0 +0.000% PYBV10
     mimxrt:    +0 +0.000% TEENSY40
        rp2:    +0 +0.000% RPI_PICO
       samd:    +0 +0.000% ADAFRUIT_ITSYBITSY_M4_EXPRESS

tannewt added a commit to tannewt/circuitpython that referenced this pull request Jul 7, 2023
don't consider refresh areas for hidden groups or tilegrids
@IhorNehrutsa IhorNehrutsa requested a review from stinos July 17, 2023 10:42
@IhorNehrutsa
Copy link
Contributor Author

@robert-hh
May you review this PR?
Thanks

Example in #10854

py/mpprint.h Outdated
@@ -80,3 +80,52 @@ int mp_vprintf(const mp_print_t *print, const char *fmt, va_list args);
#endif

#endif // MICROPY_INCLUDED_PY_MPPRINT_H
Copy link
Contributor

Choose a reason for hiding this comment

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

This line must be at the end of the file.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

And yet no.
We need to redefine MP_DEBUG_PRINT in each individual file.

@IhorNehrutsa IhorNehrutsa requested a review from robert-hh July 18, 2023 04:31
@IhorNehrutsa
Copy link
Contributor Author

@dpgeorge @stinos @iabdalkader @all_world
Are reviews/feedbacks possible this year? Or next year?
May add to the https://github.com/micropython/micropython/milestone/4 ?
Thanks.

@stinos
Copy link
Contributor

stinos commented Jul 28, 2023

There's a bunch of details I'd like to see different (the name 'PRN' is vague and a weird abbreviation of 'print', the levels not having gaps between them, the content of the message not being configurable, example code not using the macros but level numbers which is rather confusing) but: so far only one person expressed interest, I'd first like to see feedback from others as to whether they think this would be a useful addition.

@IhorNehrutsa
Copy link
Contributor Author

IhorNehrutsa commented Jul 28, 2023

the name 'PRN'

I will agree with any name (PRN/PRINT/LOG/LOG/DBG/DEBUG etc), but to finally have it.

the levels not having gaps between them

The levels may be as follows:

#define MP_PRN_SUPPRESS 0 // SUPPRESS all messages. Use it in the release version.
#define MP_PRN_CRITICAL 15 // For the most CRITICAL errors, often requiring a system reset. Use a message with this level, if possible, raising an exception.
#define MP_PRN_ERROR 35 // ERROR requiring program restart, use message with this level before raising an exception.
#define MP_PRN_WARNING 50 // WARNING, something went wrong, but you can fix it with additional operations in code right now or may ignore it.
#define MP_PRN_INFO 65 // INFO, it is interesting and useful for understanding a bug.
#define MP_PRN_DEBUG 85 // DEBUG, more detailed information, dig deeper.
#define MP_PRN_TRACE 100 // TRACE, show a flow of the algorithm, like enter/exit a function.

@IhorNehrutsa
Copy link
Contributor Author

@andrewleech
May you review this PR?
Thanks.

@andrewleech
Copy link
Contributor

I previously thought I'd want something like this, but in practice I've only ever wanted debug prints to be on or off in just one file or set of files at a time, when I'm working on low level features in that one file / module.

I definitely would not want any kind of global debug printing because the messages for the module under development would be lost in the noise.

It would be handy to be able to turn debug printing on/off on a file by file basis without having to modify the file, just to avoid accidentally committing the enabled debug printing. Not sure how this would look in practice though.

Personally I don't really see the value in global debug levels, but maybe that's just me.

@IhorNehrutsa
Copy link
Contributor Author

MP_PRN_LEVEL and MP_PRN() are not GLOBAL but LOCAL for _.c files.

MP_PRN_LEVEL and MP_PRN() are outside the mprint.h definition MICROPY_INCLUDED_PY_MPPRINT_H:

#ifndef MICROPY_INCLUDED_PY_MPPRINT_H
#define MICROPY_INCLUDED_PY_MPPRINT_H
...
#endif // MICROPY_INCLUDED_PY_MPPRINT_H




#if defined(MP_PRN_LEVEL) && (MP_PRN_LEVEL > 0)
...
#define MP_PRN(level, ...) \
  ...
#endif

in file1.c:

...
#define MP_PRN_LEVEL 0
#include "py/mpprint.h"
...
MP_PRN(3, "test print file1.c")

in file2.c

...
#define MP_PRN_LEVEL 3
#include "py/mpprint.h"
...
MP_PRN(3, "test print file2.c")

so there is no printing from file1.c and there is printing from file2.c

py/mpprint.h Outdated
if ((0 < level) && (level <= MP_PRN_LEVEL)) { \
mp_printf(MP_PYTHON_PRINTER, " MP_PRN_LEVEL=%d : ", level); \
mp_printf(MP_PYTHON_PRINTER, __VA_ARGS__); \
mp_printf(MP_PYTHON_PRINTER, "\t : FUNC=%s LINE=%d FILE=%s\n", __FUNCTION__, __LINE__, __FILE__); \
Copy link
Contributor

Choose a reason for hiding this comment

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

This is a very verbose line to be printing at all levels; on many boards the uart output can be quite slow so more text here can seriously slow down the program

Copy link
Contributor Author

Choose a reason for hiding this comment

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

My experience with debugging two files showed satisfactory speed. Most of the time I didn't print too much information by lowering MP_DEBUG_PRINT_LEVEL or pushing MP_DEBUG_PRINT to a level above MP_DEBUG_PRINT(MP_DEBUG_PRINT_XXX +1, ...) or two
MP_DEBUG_PRINT(MP_DEBUG_PRINT_XXX +2, ...).
In extreme cases, a developer can correct MP_DEBUG_PRINT as he wishes.

Copy link
Contributor

@andrewleech andrewleech Sep 2, 2023

Choose a reason for hiding this comment

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

This is highly dependent on the particular board in use, and the importance of speed in the code bring tested. The existing debug prints lines in much of the Bluetooth code for instance are very short because it breaks Bluetooth if they're much longer ...

py/mpprint.h Outdated
#define MP_PRN_WARNING 3 // WARNING, something went wrong, but you can fix it with additional operations in code right now or may ignore it.
#define MP_PRN_INFO 4 // INFO, it is interesting and useful for understanding a bug.
#define MP_PRN_DEBUG 5 // DEBUG, more detailed information, dig deeper.
#define MP_PRN_TRACE 6 // TRACE, show a flow of the algorithm, like enter/exit a function.
Copy link
Contributor

Choose a reason for hiding this comment

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

These defines would need to be above the #ifdef so they can be used to define the desired level

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Moved upper

py/mpprint.h Outdated
#endif
/*
// How to use:
// Set MP_PRN_LEVEL in developed *.C or *.CPP file, for example
Copy link
Contributor

Choose a reason for hiding this comment

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

I think it'd make sense to have any docs like this above the code rather than under it, and set by level name not number

Copy link
Contributor Author

Choose a reason for hiding this comment

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

In fact, numbers are more convenient than names in debugging. You may try...

Copy link
Contributor

@andrewleech andrewleech Sep 2, 2023

Choose a reason for hiding this comment

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

We'll just have to agree to disagree on this point then. The python logging module can have its levels defined in numbers... but the vast majority of users (myself incurred) prefer to use level names.

Also, a new developer coming across a C file with some debug "info" prints already in it will logically want to "enable info level" to see them. They wouldn't know what number this is without hunting through headers to get here.

py/mpprint.h Outdated
@@ -80,3 +80,59 @@ int mp_vprintf(const mp_print_t *print, const char *fmt, va_list args);
#endif

#endif // MICROPY_INCLUDED_PY_MPPRINT_H
Copy link
Contributor

Choose a reason for hiding this comment

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

This is the end of file include guard, and should remain at the end of the file.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

And yet no.
We need to redefine MP_DEBUG_PRINT in each individual file.

Copy link
Contributor

Choose a reason for hiding this comment

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

I find this sort of non-standard coding pattern to be confusing, there's a fair chance a future programmer looking at it will think so too and "fix" it, breaking your intended behaviour without realising it.

I believe the print functionality really should be written / used in a way that doesn't take this.

Keep in mind that all C files are compiled in isolation, they all get their own copies of defines & macros included separately.

Also please don't mark concerns as resolved unless the reviewer says as such. I see now I'm not the first person to raise this particular issue.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Keep in mind that all C files are compiled in isolation, they all get their own copies of defines & macros included separately.

I tried to move #endif // MICROPY_INCLUDED_PY_MPPRINT_H to the end of the file
and set MP_DEBUG_PRINT_LEVEL BEFORE any "MicroPython's *.h" includes in two _.c files.
The MP_DEBUG_PRINT() worked only in one file. :(
It may be cmake particularity, I don't know.
I keep it as is.

py/mpprint.h Outdated
// In reality, you may use your own classification of debug levels.

#if defined(MP_PRN)
#undef MP_PRN
Copy link
Contributor

Choose a reason for hiding this comment

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

I think this under should be removed, and instead define the command below only if it's not already defined. It should ideally be possible for people to define their own command in mpconfigboard.h

Copy link
Contributor Author

Choose a reason for hiding this comment

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

mprint.h was included early in files and MP_DEBUG_PRINT was defined previously as nothing

#define MP_DEBUG_PRINT(level, ...) 

so we need undef and then define MP_DEBUG_PRINT again

#if defined(MP_DEBUG_PRINT)
#undef MP_DEBUG_PRINT
#endif

#define MP_DEBUG_PRINT(level, ...) \
    do { \
     ...

Unfortunately, this blocks redefining in mpconfigboard.h

@IhorNehrutsa IhorNehrutsa changed the title py/mpprint.h: Add MP_PRN() macro and MP_PRN_LEVEL. py/mpprint.h: Add MP_DEBUG_PRINT() macro and MP_DEBUG_PRINT_LEVEL. Sep 1, 2023
@IhorNehrutsa
Copy link
Contributor Author

@projectgus
Could you review this?
Thanks.

@projectgus
Copy link
Contributor

projectgus commented Sep 26, 2023

@IhorNehrutsa Sure, I'm happy to!

I have some questions about the implementation, but first I have two "big picture" questions:

  • What problem does this solve?
  • Can you please walk step by step through a hypothetical example that explains how a developer would use this to find and debug some MicroPython behaviour?

To summarise my understanding of the current situation for extra printf debug output, the choices are:

  1. Set MICROPY_DEBUG_VERBOSE and MICROPY_DEBUG_PRINTERS for the whole build, you get a lot of debug output that may or may not be useful.
  2. Temporarily change the guard in a single .c file from #if MICROPY_DEBUG_VERBOSE to #if 1 // MICROPY_DEBUG_VERBOSE and check the following line is #define DEBUG_printf printf or similar. This is a hacky-but-quick way to get verbose output from just this C file, on ports that implement printf.

Speaking for myself, I don't use option 1 much (too much output to be useful). I use option 2 sometimes. Difficulty mixing the simple printf hack with mpremote mount or mpremote run means I don't use it that much either, though.

(I see @andrewleech essentially said similar things, above.)

This has been on my mind for a while because I noticed debug_printf is defined multiple times in multiple files (especially in ports and extmod) as DEBUG_printf or debug_printf. It would be nice if all instances of that macro are removed and replaced with a common standard debug macro. I

Given how hacky option 2 is, and the fact MICROPY_DEBUG_PRINTERS is required to actually get an implementation of DEBUG_printf() in the build, then I agree with this part of @iabdalkader's comment. However, that part could be standardised and made simpler for developers with some tweaks to the existing macros.

@IhorNehrutsa
Copy link
Contributor Author

IhorNehrutsa commented Sep 26, 2023

Set MICROPY_DEBUG_VERBOSE and MICROPY_DEBUG_PRINTERS for the whole build, you get a lot of debug output that may or may not be useful.

When I set MICROPY_DEBUG_VERBOSE and MICROPY_DEBUG_PRINTERS in micropython\ports\esp32\mpconfigport.h

#define MICROPY_DEBUG_PRINTERS              (1)
#define MICROPY_DEBUG_VERBOSE               (1)

I get Guru Meditation Error

ELF file SHA256: 1977f7c019577f76

Rebooting...
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:4728
load:0x40078000,len:14780
ho 0 tail 12 room 4
load:0x40080400,len:3368
entry 0x400805cc
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x40098227  PS      : 0x00060630  A0      : 0x800dab09  A1      : 0x3ffcecc0  
A2      : 0x00000000  A3      : 0x00000000  A4      : 0x00000000  A5      : 0x00000000  
A6      : 0x3ffdfa14  A7      : 0x3ffcfa14  A8      : 0x80098227  A9      : 0x3ffceca0  
A10     : 0x00000002  A11     : 0x3ffdfa10  A12     : 0x3ffc35f8  A13     : 0x3ffc35f4  
A14     : 0x00000001  A15     : 0x80000002  SAR     : 0x00000019  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  


Backtrace: 0x40098224:0x3ffcecc0 0x400dab06:0x3ffced00 0x400d80f2:0x3ffced20 0x400f5c49:0x3ffced40 0x400dce89:0x3ffced60 0x400dd3b6:0x3ffced80 0x400e97e1:0x3ffcedf0 0x400dbfa4:0x3ffcee40 0x400d7d8d:0x3ffcee60

@robert-hh
Copy link
Contributor

1_694_032 is much smaller than 16_777_216!

@IhorNehrutsa
Copy link
Contributor Author

1_694_032 is much smaller than 16_777_216!

Oops! You are right! My guess is wrong.

@IhorNehrutsa
Copy link
Contributor Author

When I set MICROPY_DEBUG_VERBOSE and MICROPY_DEBUG_PRINTERS in micropython\ports\esp32\mpconfigport.h to

#define MICROPY_DEBUG_PRINTERS              (1)
#define MICROPY_DEBUG_VERBOSE               (0)

and add in single *.c source file

#if 1 // MICROPY_DEBUG_VERBOSE // print debugging info
#define DEBUG_PRINT (1)
#define DEBUG_printf DEBUG_printf
#else // don't print debugging info
#define DEBUG_PRINT (0)
#define DEBUG_printf(...) (void)0
#endif

DEBUG_printf() works as expected in that file.

IhorNehrutsa and others added 4 commits October 6, 2023 09:17
Move MP_DEBUG_PRINT_XXX constants upper to the #if MICROPY_INCLUDED_PY_MPPRINT_H/#endif block.

Co-Authored-By: Andrew Leech <3318786+andrewleech@users.noreply.github.com>
Add gaps between MP_DEBUG_PRINT_XXX levels.
Move `How to use:` upper before #define MP_DEBUG_PRINT().
Print level names instead of the numbers.

Signed-off-by: Ihor Nehrutsa <IhorNehrutsa@gmail.com>
@IhorNehrutsa
Copy link
Contributor Author

IhorNehrutsa commented Jan 12, 2024

Closed in favor #13400

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
py-core Relates to py/ directory in source
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants