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?
Parent task T78164 -> simple to follow, but for devs
Initial Proposal -> not really interesting
Project Details -> very detailed and technical
Initial devtalk thread -> not really interesting, same as Initial proposal
My branch named soc-2020-info-editor
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
I am converting a lot of prints into CLOG in my branch and would like to gather some feedback, introduce certain style for logs.
G.debug and G.debug_value
// 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 usecasesSo when to use flags?
if (G.debug & G_DEBUG_GPU) gpu_debug_init()if (G.debug & G_DEBUG_GPU) CLOG_INFO(...)
G_DEBUG_JOBS)After studying flags usage in blender code:
G_DEBUG changes mouse grab behaviourG_DEBUG_WM adds internal operators in F3 search,G_DEBUG_DEPSGRAPH_NO_THREADS use only 1 threadG_DEBUG_GPU_MEM gpu memory in status bar -G_DEBUG_GPU does some magic with GPU debuggingG_DEBUG_IO enables sanity checks on file writeG_DEBUG_GPU_FORCE_WORKAROUNDS - some magic with GG parametersIn 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);
}
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.
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:
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)// 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.
// 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.
// 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.
// 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.
CLOG_ERROR(...); BLI_assert(0); // fails only in debug builds or
CLOG_FATAL(...); // automatically crashes and creates coredump
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);
}
}
glog log systemCurrently 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).
Does current logging setup fit with cpp style of coding?
Not so important questions, but I am going to write a lot of logs.
%s? single or double? Helps especially on empty stringsvariable=value or variable: value
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);
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?
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
yep this command does not do anything. Even more, there are gotchas.
--debug flags, exampleblender --debug-cycles
--log-level does not do anything by itself. You need to enable logger.LogRef xd, example:blender --log-level -1 --log ".*". (enble all loggers)-1 means all possible log levels, .* - all possible loggers--debug flag is enabled!!bke.*, ed.*, bpy.*, wm.* and couple more)--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)
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
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.
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.
@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.
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.
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.
I am trying to create some sensible filter UI for logging.
I would like to include features:
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:
