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 proposal

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 if with debug check is doubling on functionality (you need to enable this log anyway)

G.debug valid usecases

So when to use flags?

  • use flags when there is some kind of system to init, especially if it can be done only on startup: 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(...)
  • additionally notice how little some debug flags are used in code (eg. G_DEBUG_JOBS)

After studying flags usage in blender code:

  • most times debug is a gurad for print and can be converted to log
  • these flags change logic (incomplete list):
    – G_DEBUG changes mouse grab behaviour
    – G_DEBUG_WM adds 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

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);
// ...
}
// usage:
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 * (consistent 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);
// passing log reference seems also ok:
void ED_undo_object_set_active_or_warn(ViewLayer *view_layer,
                                       Object *ob,
                                       const char *info,
                                       CLG_LogRef *log);
// usage:
static CLG_LogRef LOG = {"ed.undo.mball"};
ED_undo_object_set_active_or_warn(CTX_data_view_layer(C), us->elems[0].obedit_ref.ptr, us_p->name, &LOG);

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

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 usually 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 (already done in my branch soc-2020-info-editor)

Avoid dumping information to console

// meh:
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

// 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 I would avoid it, unless there is a good reason to use it. Good reason are ex. TIMEIT functions.

Local PRINTF

// antipattern:
#define PRINTF(message) printf(message)
void very_long_function() { PRINTF("blah"); }
// better:
static CLG_LogRef LOG = {"ed.file_name"};
#define CLOG_FILE_NAME(message) CLOG_INFO(&LOG, message);
void very_long_function() { CLOG_FILE_NAME("blah"); }

Rationale: Well if you have to use macro, I don’t mind doing it this way.

Be quiet!

// implementation 1:
wmOperatorType *WM_operatortype_find(const char *idname, bool quiet){ // this function is called many times
    if (!quiet) { CLOG_VERBOSE(WM_LOG_OPERATORS, 2, "search for unknown operator '%s', '%s'", idname_bl, idname);  }
}
// implementation 2:
wmOperatorType *WM_operatortype_find(const char *idname, CLG_LogRef *log){ // log can be NULL
    if (log) { CLOG_VERBOSE(log, 2, "search for unknown operator '%s', '%s'", idname_bl, idname);  }
}

I would avoid any kind of vebose/quiet argument, but I am open for discussion.

Assert or log fatal?

CLOG_ERROR(...); BLI_assert(0); // fails only in debug builds or
CLOG_FATAL(...); // automatically crashes and creates coredump

Logs from third party libraries

Third party library with custom log system (like ffmpeg)

Well built 3rd party lib will have logging callback. We can easily connect such to bledner log system:

static void ffmpeg_log_callback(void *ptr, int level, const char *format, va_list arg){
// convert as needed and end with CLOG_*
}

But UI for such libraries needs to be developed on one by one basis, currently we do for example:

void IMB_ffmpeg_init(void) {
  if (G.debug & G_DEBUG_FFMPEG) {
    av_log_set_level(AV_LOG_DEBUG);
  }
}

Library with glog log system

Currently blender integrates 2 libs that use glog, what causes strange code to avoid double initialization of glog:

#ifdef WITH_LIBMV
  libmv_initLogging(argv[0]);  // inits glog and sets some settings
#elif defined(WITH_CYCLES_LOGGING)
  CCL_init_logging(argv[0]); // inits glog and sets some (different) settings
  // later it configures glog: SetCommandLineOption("stderrthreshold", severity_fatal);
#endif

Setting options for glog is quite strange, because it uses another lib gflags for managing its settings.
Good news is that we can set callback for glog (glog calls it LogSink) to integrate it with blender.
Bad news is that glog is pretty complex thus hard to integrate (at least too hard for me for now).

Questions

Logging in cpp files

Does current logging setup fit with cpp style of coding?

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)

2 Likes

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

2 Likes

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

4 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

7 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
3 Likes