GSoC 2020: Info Editor Improvements - Discussion and Suggestions (logs, reports & friends)

I will use this topic to discuss various things connected to Info editor improvements.

So far I have one question to devs: what are the most important features to add to logging system and info editor?

4 Likes

Now that Blender have Bold fonts could we see the info editor shortcuts with bold letters instead of the actual icons?

I have tested this feature in 10-15 users and nobody have able to see that shorcuts because the icons made it impossible to read and understand.

Hi. Your project details are a little to technical for me to understand but I believe I saw it mentioned somewhere that one the intentions is to be able to debug (having the error info be displayed in the info viewer) without opening the command prompt? That would be great to have when doing small simple scripts

@Alberto sorry I do not understand what you are talking about…

@dimitar I agree, those details are technical, this is quite new working experience for me.

python errors show up in info editor.
Do you want to have visible print("sth") in info editor instead of console? I am not sure if it is good idea to redirrect pythons stdout to blender info editor, it might be problematic, I need to investigate. Instead it might be better done by introducing new python API for logging in blender that would integrate with pythons build in logging module. You can think about is like his: bpy.log.info("sth"), but this is very unrefined idea.

Use this type of shortcuts style

instead of the actual icons that are hard to understand. The original reason was that blender didn’t have bold font support, but it changed thie last week

1 Like

Logging - best practices

I am converting a lot of prints into CLOG in my branch and would like to gather some feedback, introduce certain style for logs.

Reduce use of G.debug and G.debug_value

Simple cases

// catastrophy:
if (G.debug_value > 0)
  printf("cloth_free_modifier_extern\n");
// antipattern:
if (G.debug & G_DEBUG) {
  CLOG_INFO(&LOG, 1, "redo_cb: operator redo %s", op->type->name);
}
// better just:
CLOG_INFO(&LOG, 1, "redo_cb: operator redo %s", op->type->name);
// antipattern:
if (G.debug & G_DEBUG) {
  // allocate memory, prepare data to be printed
  // printf(...)
  // free memory
}
// better:
static CLG_LogRef LOG = {"bke.anim_sys"};
if (CLOG_CHECK_LEVEL(&LOG, 0)) { // in master called CLOG_CHECK
  // allocate memory, prepare data to be printed
  // CLOG_INFO(&LOG, 0, "why is 6 afraid of 7?")
  // free memory
}

Rationale: CLOG_INFO is macro which introduces implicit check: to print this info logger LOG must be enabled and log level must be minimum 1. There is no performance improvement (to my knowledge) and this if is doubling on functionality (you need to enable this log anyway)

G.debug valid usecases

So when to use flags?

  • kind of makes sense when there is some kind of system to init: if (G.debug & G_DEBUG_GPU) gpu_debug_init()
    – now when you have flag, every log you introduce need to be guarded if (G.debug & G_DEBUG_GPU) CLOG_INFO()
  • but we can do the same with log, no point in using flag… if (CLOG_CHECK(LOG, 0)) gpu_debug_init()
  • maybe use flags when logic changes:
  if (G.debug & G_DEBUG_IO && mainvar->lock != NULL) {
    BKE_report(reports, RPT_INFO, "Checking sanity of current .blend file *AFTER* save to disk"); // I would convert to log, see next paragraph
    BLO_main_validate_libraries(mainvar, reports); // adds validation to logic
  }
  • but again we can do the came with CHECK_LOG
  • but when flag changes user interface seems valid use case, see G_DEBUG_GPU_MEM
  • additionally notice how little some debug flags are used in code (eg. G_DEBUG_JOBS)

No conclusions on this topic…

After studying flags usage in blender code:

  • 90% of times debug is a gurad for print and can be converted to code
  • the only one that changes logic are
    G_DEBUG - changes mouse grab behaviour
    G_DEBUG_WM (add internal operators in F3 search),
    G_DEBUG_DEPSGRAPH_NO_THREADS use only 1 thread
    G_DEBUG_GPU_MEM gpu memory in status bar -
    G_DEBUG_GPU does some magic with GPU debugging
    G_DEBUG_IO enables sanity checks on file write
    G_DEBUG_GPU_FORCE_WORKAROUNDS - some magic with GG parameters
    G_DEBUG_XR* - - todo
    G_DEBUG_GHOST - todo
    – not mentioned flags can does not have logic-changing function

Should enabling debug flag trigger enabling loggers?
Should enabling debug flag trigger UI changes?

Should G.debug flags use reports or logs?

In my humble opinion user should not see any more Reports if debug flags are enable, but I am open minded about it. Example to study:

bool BLO_main_validate_libraries(Main *bmain, ReportList *reports) {
// ...
   BKE_reportf(reports,
               RPT_ERROR,
               "ID %s is in local database while being linked from library %s!",
               id->name,
               id->lib->filepath);
// ...
}
// validation is always guarded by similar if:
if (G.debug & G_DEBUG_IO && mainvar->lock != NULL) {
  BKE_report(reports, RPT_INFO, "Checking sanity of current .blend file *BEFORE* save to disk");
  BLO_main_validate_libraries(mainvar, reports);
  BLO_main_validate_shapekeys(mainvar, reports);
}

Debug functions

To prety print struct use function *_sprintfN which returns (newy allocated) char * (consistant with BLI_sprintfN & friends)

void DM_debug_print_cdlayers(CustomData *data) { prinf("...") }
char *DM_debug_sprintfN_cdlayers(CustomData *data) { // use DynStr to create and return cstring */ }
// usage 1:
CLOG_STR_INFO_N(&LOG, 1, DM_debug_sprintfN_cdlayers(sth)); // frees memory 
// usage 2:
char *message = DM_debug_sprintfN_cdlayers(sth);
CLOG_INFO(&LOG, 1, "sth=%s", message); 
MEM_freeN(message);

Rationale: CLOG logs the function you are calling from. It would be useless to always have it called from DM_debug_print_cdlayers. Not sure how it impacts performance, feel free to comment.

Should we allow returning NULL from such functions? NULL is annoying to deal with.

Clearly separate reports from logging

Assume that reports are for users, logs are for devs. Unfortunately this is is not clear.
If you want logs, you need to enable them. Right now it is really messed up around the code base. Also:

  • remove debug report type - in the codebase there is one usage of it. You do not want to feed user with debugs. Just use log.
  • remove storelevel from ReportList - this was a feature allowed to not store your reports, but only print it to console. Again, use logs. Instead introduce logger that will log reports to console
  • these changes are already in my branch soc-2020-info-editor (currently bit unstable)
if (error & NTREE_DOVERSION_NEED_OUTPUT) {
  BKE_report(fd->reports, RPT_ERROR, "Eevee material conversion problem. Error in console");
  printf(
      "You need to connect Principled and Eevee Specular shader nodes to new material "
      "output "
      "nodes.\n");
}
// better 
BKE_report(fd->reports,
           RPT_ERROR,
           "Eevee material conversion problem. \n"
           "You need to connect Principled and Eevee Specular shader nodes to new material "
           "output nodes");
}

This printf was introduced, because window manager is not initialized yet and report can not be displayed or saved. In branch (possibly) fixed that problem.

Local debug macros

// antipattern??
// at beginng of file defining custom macro
// #define PATH_DEBUG 
// usage in code
#ifdef PATH_DEBUG
    printf("\t%s found: %s\n", __func__, targetpath);
#endif
// at the end
#ifdef PATH_DEBUG
#  undef PATH_DEBUG
#endif
// or using macro that comes from build settings
#if defined(DEBUG)
#endif

Rationale: Using macro improves performance but imho this is not the way to solve the problem. In general, just use log. Todo: example where the use of macro is good?

// antipattern??
#define PRINTF(message) if (verbose) CLOG_INFO(&LOG, 0, message)
void very_long_function(bool verbose) { /* PRINTF("because 7 8 9)") */}

Rationale: I do not know what to think about it… One thing I would say that function should not accept any king of versose/quiet argument (example WM_operatortype_find). Leave logging for loggers.

assert or log fatal?

CLOG_ERROR(...); assert(0); // or
CLOG_FATAL(...); // automatically crashes and creates coredump

Questions

Documenting logger?

You see a logger "bke.action". So what kind of information does it give you? All you know it is sth about action, armature. Can we do better? Loose ideas (that I am not sure how to implement), remember I want to show loggers in UI:

  • add doctring to definition
  • gather information about log usage (at compile time) and show ahead of time:
    – which verbosity levels are used
    – which severity levels are used
    – which functions and file have CLOG_*

Would it be usefull or is it just getting fancy?

Logging in cpp files

Does current logging setup fit with cpp style of coding?

Indenting

Common pattern is to have indented rows to indicate child parent relationship in logs. It does not work well when printing all other information (file-line, function). Do we want some systematic solution?

Verbosity levels in CLOG_INFO

The highest verbosity we use in code is 5 and we have whole int. Any tips how to use that value properly?

When to log?

Good example to study is source/blender/blenkernel/intern/cloth.c (experimental commit: cloth.c - print to log) as those logs might have been useful when developing feature, but in long run are kind of pointless. So again, when to log?

Logs from third party libraries

todo - investigate

ffmpeg

Very easy to turn to log, this lib uses single callback
static void ffmpeg_log_callback(void *ptr, int level, const char *format, va_list arg)

Small big questions about style

Not so important questions, but I am going to write a lot of logs.

  • put quotes on %s? single or double? Helps especially on empty strings
  • include pointer to variable?
  • variable=value or variable: value
  • can we accomplish some of it with macros? (or should we?)
  • Capitalize or not to capitalize?
CLOG_INFO(&LOG, 0, "writing userprefs: %s ok'", filepath);
CLOG_INFO(&LOG, 0, "Writing userprefs ok filepath='%s'(%p)", filepath, filepath);
3 Likes

I’m not sure if this is already possible,
I would love an option to turn off certian types of logs when rendering via console.
Right now it writes a new log every few samples and makes it difficult to read logs that are actually usefull like render time of the last frame.
Is something like this related to this project?

Also I think it would be wise to consider increasing time between writing logs about render progress. All they really say is “it’s still rendering just like a second ago”. Maybe write log after each tile only?

1 Like

Thanks for feedback!
Can you share the command you use? I can look into that. So far I did not have time to touch logging of render/cycles/depsgraph.
Currently you would control verbosity of logs with command line --log --log-level --verbosity --debug (and friends). It may be the case that rendering does not even uses logging (only printing to console), then it will be impossible to control amount and type of logs.

The desired log system will use log types and verbosity (--log "render.*" ) but currently I do not plan separating logs to different files, not sure if there is a need.
If you can pin point specific information about rendering I can look into that.

Thanks for the answer.
I tried using using --log-level argument with some help from the documentation https://docs.blender.org/manual/en/latest/advanced/command_line/arguments.html#logging-options
But this command doesn’t seem to do anything. I tried using argument 0 and 20 and I couldn’t see any difference.
I write it like this:
blender -b --log-level 0 filename.blend -a

1 Like

yep this command does not do anything. Even more, there are gotchas.

  • currently blender uses mostly prints. Prints are enabled by --debug flags, example
    blender --debug-cycles
  • --log-level does not do anything by itself. You need to enable logger.
    – How do you know loggers names? Search code base for LogRef xd, example:
    blender --log-level -1 --log ".*". (enble all loggers)
    -1 means all possible log levels, .* - all possible loggers
    – watch out! some loggers will work only if specific --debug flag is enabled!!
    – there are no loggers defined for rendering (if you want to play with other loggers, there are bke.*, ed.*, bpy.*, wm.* and couple more)
  • there is also --verbose. it sets log level for cycles and libmv(whatever that is)

In the end I am pretty sure this will work: blender --debug-all --log-level -1 --log ".*,^wm.*" (disable wm, it spams too much)

1 Like

Thank you for you work here. The ability to get all (python) bug reports printed in the Info Editor, so system console is not needed, is nothing short of brilliant.

I don’t know if this is within your ambitions for the info editor, but the quite useful “Replay”(unexposed) function is imo quite useful, but it fails on most occasions because of bad context. If the log also stored the context, the replay could re-run the commands in the right contexts. Old bug-report: https://developer.blender.org/T68656

1 Like

Personally I never used this feature, although I have seen it commented in code. Is it different from Edit -> Repeat History? There is possible fix for that, I will keep an eye on this.

Generally fine with those rules, although I would not confuse debug flags with log level (verbosity).

Debug flags allow you to completely turn on or off some parts of the logging (done through printf currently most of the time), this is not the same and imho should work in a complementary way with log verbosity?

Personally I would just create new logger. If you want to debug only menus, just do logger "wm.menus" instead:

if (G.debug & G_DEBUG_WM) {
    printf("%s: opening menu \"%s\"\n", __func__, mt->idname);
}

I would like to hear your thoughts on logs in 1st party libraries (libraries in /intern). Ghost in particular has no consistency.

1 Like

gpu, ghost, depgrah are on my todo list. I started de-printf-ing from /source.

So far (on branch) I gave some love to /source: window manager (new log wm.session - save, autosave), blenfont and various minor prints in blenkernel

I am mostly converting existing prints to logs, and removing the ones that make no sense, I tried avoiding huge changes as I am not super familiar with code.

In /intern i tried adding logs for /guardedalloc but failed so far due to circular dependency on clog, I do not want to deal with this for now. This is the only case of circular dependency in intern and i had to start from it…

General approach is to find prints, add log (or multiple), add various verbosities.

In what way is it inconsistent? Is it prints mixed with logs or do you mean the contents of what is being logged? If you tell me more I can probably make your life easier.

2 Likes

@JerzyGorski In this very moment I am tweaking logs in rendering. In code there is struct RenderStats that is printed every 25 samples. in current blender logs can be printed only in background mode, I am going to make them dependent on logger. This is (the most verbose) log from rendering 3 frames. Remeber that logs finely controlled. Should I make this log in parse-able format? Does anyone cares?

INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:197 render_print_save_message: Saved: '/tmp/0001.png'
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2305 do_write_image_or_movie:  Time: 00:00.75
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2315 do_write_image_or_movie:  (Saving: 00:00.40)
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.04 |  Syncing Cube |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.32M (Peak 134.41M) | Time:00:00.04 |  Syncing Light |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.32M (Peak 134.41M) | Time:00:00.04 |  Syncing Camera |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.05 |  Rendering 1 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.17 |  Rendering 26 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.27 |  Rendering 51 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.31 |  Rendering 64 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:197 render_print_save_message: Saved: '/tmp/0002.png'
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2305 do_write_image_or_movie:  Time: 00:01.26
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2315 do_write_image_or_movie:  (Saving: 00:00.27)
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.03 |  Syncing Cube |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.32M (Peak 134.41M) | Time:00:00.04 |  Syncing Light |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.32M (Peak 134.41M) | Time:00:00.04 |  Syncing Camera |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.05 |  Rendering 1 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.14 |  Rendering 26 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.22 |  Rendering 51 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.26 |  Rendering 64 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:197 render_print_save_message: Saved: '/tmp/0003.png'
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2305 do_write_image_or_movie:  Time: 00:01.20
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2315 do_write_image_or_movie:  (Saving: 00:00.28)

This is very new, it is not even commited.

There are some user experience quarks regarding log related UI that I will address in this post.

Enable disable logs from user preferences

Corner case: those values can be overridden from command line, but we still want to store them in preferences.

Solutions: Dedicated buttons for saving log preferences. These settings are omitted from default save mechanism. Add presets as a bonus.

image

2 Likes

I added all possible report types to UI as experiment. This is a bit more than in https://developer.blender.org/D6926. We have them defined in code, we just never bothered to make a UI for it.
Zrzut ekranu z 2020-08-06 12-09-47

3 Likes

I am trying to create some sensible filter UI for logging.

I would like to include features:

  • filter log severity (as enum or flag enum)
  • separate search fields log type, file line, log function
    – the UI is borrowed from this:
    image
  • ideally I would like to filter verbosity by ranges, but I can not figure out sensible UI for this king of feature

I am not sure how to expose log message formatting, so far I went with flag approach.

As for the context menu I am planning operations:

  • exclude log type/function/file/this line
  • sync selection - across all open info editors select the next visible log entry
  • copy all/file
2 Likes