From 15d5f957acec72a1ab4c7834f960c724114e4779 Mon Sep 17 00:00:00 2001 From: Brecht Van Lommel Date: Thu, 12 Jun 2025 02:20:00 +0200 Subject: [PATCH] Logging: Use CLOG for render progress * Add render category, which is automatically enabled when using -f or -a command line flags for background rendering. * Add extra logs to mention scene, view layer and frame ahead of time rather than including it in every line. * Remaining time was removed from Cycles, this will be added back for animations at the render pipeline level. Pull Request: https://projects.blender.org/blender/blender/pulls/140244 --- intern/cycles/blender/session.cpp | 57 +++++++------------ source/blender/blenkernel/intern/image.cc | 2 +- .../blender/blenkernel/intern/image_save.cc | 6 +- .../blender/editors/render/render_internal.cc | 9 ++- source/blender/render/CMakeLists.txt | 1 + source/blender/render/RE_pipeline.h | 2 +- source/blender/render/intern/engine.cc | 12 +++- source/blender/render/intern/pipeline.cc | 44 ++++++-------- source/creator/creator_args.cc | 10 ++++ 9 files changed, 69 insertions(+), 74 deletions(-) diff --git a/intern/cycles/blender/session.cpp b/intern/cycles/blender/session.cpp index 8ba31c2c090..208d11cc4a2 100644 --- a/intern/cycles/blender/session.cpp +++ b/intern/cycles/blender/session.cpp @@ -990,53 +990,36 @@ void BlenderSession::update_status_progress() string timestatus; string status; string substatus; - string scene_status; - double progress; - double total_time; - double remaining_time = 0; - double render_time; - const float mem_used = (float)session->stats.mem_used / 1024.0f / 1024.0f; - const float mem_peak = (float)session->stats.mem_peak / 1024.0f / 1024.0f; - get_status(status, substatus); - get_progress(progress, total_time, render_time); - - if (progress > 0) { - remaining_time = session->get_estimated_remaining_time(); + if (background && !substatus.empty()) { + status += " | " + substatus; } + double progress; + double total_time; + double render_time; + get_progress(progress, total_time, render_time); + + const float mem_used = (float)session->stats.mem_used / 1024.0f / 1024.0f; + const float mem_peak = (float)session->stats.mem_peak / 1024.0f / 1024.0f; if (background) { - if (scene) { - scene_status += " | " + scene->name; - } - if (!b_rlay_name.empty()) { - scene_status += ", " + b_rlay_name; + + if (progress > 0) { + const double remaining_time = session->get_estimated_remaining_time(); + if (remaining_time > 0) { + timestatus = "Remaining: " + time_human_readable_from_seconds(remaining_time) + " | "; + } } - if (!b_rview_name.empty()) { - scene_status += ", " + b_rview_name; - } - - if (remaining_time > 0) { - timestatus += "Remaining:" + time_human_readable_from_seconds(remaining_time) + " | "; - } - - timestatus += string_printf("Mem:%.2fM, Peak:%.2fM", (double)mem_used, (double)mem_peak); - - if (!status.empty()) { - status = " | " + status; - } - if (!substatus.empty()) { - status += " | " + substatus; - } + timestatus += string_printf("Mem: %dM | ", (int)ceilf(mem_used)); } const double current_time = time_dt(); - /* When rendering in a window, redraw the status at least once per second to keep the elapsed - * and remaining time up-to-date. For headless rendering, only report when something - * significant changes to keep the console output readable. */ + /* When rendering in a window, redraw the status at least once per second to keep things + * up to date. For headless rendering, only report when something significant changes to + * keep the console output readable. */ if (status != last_status || (!headless && (current_time - last_status_time) > 1.0)) { - b_engine.update_stats("", (timestatus + scene_status + status).c_str()); + b_engine.update_stats("", (timestatus + status).c_str()); b_engine.update_memory_stats(mem_used, mem_peak); last_status = status; last_status_time = current_time; diff --git a/source/blender/blenkernel/intern/image.cc b/source/blender/blenkernel/intern/image.cc index 1a33d056a75..605e438b71d 100644 --- a/source/blender/blenkernel/intern/image.cc +++ b/source/blender/blenkernel/intern/image.cc @@ -1869,7 +1869,7 @@ static void stampdata( } if (use_dynamic && stats && (scene->r.stamp & R_STAMP_MEMORY)) { - SNPRINTF(stamp_data->memory, do_prefix ? "Peak Memory %.2fM" : "%.2fM", stats->mem_peak); + SNPRINTF(stamp_data->memory, do_prefix ? "Peak Memory ddM" : "%dM", stats->mem_peak); } else { stamp_data->memory[0] = '\0'; diff --git a/source/blender/blenkernel/intern/image_save.cc b/source/blender/blenkernel/intern/image_save.cc index 283c2ffa358..e97f80e932d 100644 --- a/source/blender/blenkernel/intern/image_save.cc +++ b/source/blender/blenkernel/intern/image_save.cc @@ -40,6 +40,10 @@ #include "RE_pipeline.h" +#include "CLG_log.h" + +static CLG_LogRef LOG_RENDER = {"render"}; + using blender::Vector; bool BKE_image_save_options_init(ImageSaveOptions *opts, @@ -1039,7 +1043,7 @@ static void image_render_print_save_message(ReportList *reports, if (ok) { /* no need to report, just some helpful console info */ if (!G.quiet) { - printf("Saved: '%s'\n", filepath); + CLOG_INFO(&LOG_RENDER, 0, "Saved: '%s'", filepath); } } else { diff --git a/source/blender/editors/render/render_internal.cc b/source/blender/editors/render/render_internal.cc index 12574ef69f5..f0d193ad6ce 100644 --- a/source/blender/editors/render/render_internal.cc +++ b/source/blender/editors/render/render_internal.cc @@ -417,8 +417,8 @@ static void make_renderinfo_string(const RenderStats *rs, const uintptr_t mem_in_use = MEM_get_memory_in_use(); const uintptr_t peak_memory = MEM_get_peak_memory(); - const float megs_used_memory = (mem_in_use) / (1024.0 * 1024.0); - const float megs_peak_memory = (peak_memory) / (1024.0 * 1024.0); + const int megs_used_memory = ceilf(mem_in_use / (1024.0 * 1024.0)); + const int megs_peak_memory = ceilf(peak_memory / (1024.0 * 1024.0)); /* local view */ if (rs->localview) { @@ -469,13 +469,12 @@ static void make_renderinfo_string(const RenderStats *rs, else { if (rs->mem_peak == 0.0f) { SNPRINTF(info_buffers.statistics, - RPT_("Mem:%.2fM (Peak %.2fM)"), + RPT_("Mem:%dM, Peak %dM"), megs_used_memory, megs_peak_memory); } else { - SNPRINTF( - info_buffers.statistics, RPT_("Mem:%.2fM, Peak: %.2fM"), rs->mem_used, rs->mem_peak); + SNPRINTF(info_buffers.statistics, RPT_("Mem:%dM, Peak: %dM"), rs->mem_used, rs->mem_peak); } info_statistics = info_buffers.statistics; } diff --git a/source/blender/render/CMakeLists.txt b/source/blender/render/CMakeLists.txt index 5cbae90b3c3..c5ef1f1cbed 100644 --- a/source/blender/render/CMakeLists.txt +++ b/source/blender/render/CMakeLists.txt @@ -65,6 +65,7 @@ set(LIB PRIVATE bf::intern::guardedalloc bf_compositor PRIVATE bf::intern::atomic + PRIVATE bf::intern::clog PRIVATE bf::nodes PRIVATE bf::sequencer PRIVATE bf::windowmanager diff --git a/source/blender/render/RE_pipeline.h b/source/blender/render/RE_pipeline.h index f7dfbfb10a9..00994f245af 100644 --- a/source/blender/render/RE_pipeline.h +++ b/source/blender/render/RE_pipeline.h @@ -154,7 +154,7 @@ struct RenderStats { double starttime, lastframetime; const char *infostr, *statstr; char scene_name[MAX_ID_NAME - 2]; - float mem_used, mem_peak; + int mem_used, mem_peak; }; /* *********************** API ******************** */ diff --git a/source/blender/render/intern/engine.cc b/source/blender/render/intern/engine.cc index 46dfea90d9b..1607594994b 100644 --- a/source/blender/render/intern/engine.cc +++ b/source/blender/render/intern/engine.cc @@ -45,6 +45,8 @@ #include "WM_api.hh" +#include "CLG_log.h" + #include "pipeline.hh" #include "render_result.h" #include "render_types.h" @@ -53,6 +55,8 @@ ListBase R_engines = {nullptr, nullptr}; +static CLG_LogRef LOG = {"render"}; + void RE_engines_init() { DRW_engines_register(); @@ -530,8 +534,8 @@ void RE_engine_update_memory_stats(RenderEngine *engine, float mem_used, float m Render *re = engine->re; if (re) { - re->i.mem_used = mem_used; - re->i.mem_peak = mem_peak; + re->i.mem_used = (int)ceilf(mem_used); + re->i.mem_peak = (int)ceilf(mem_peak); } } @@ -953,6 +957,7 @@ static void engine_render_view_layer(Render *re, * dependency graph, which is only allowed if there is no grease * pencil (pipeline is taking care of that). */ if (!RE_engine_test_break(engine) && engine->depsgraph != nullptr) { + CLOG_INFO(&LOG, 0, "Rendering grease pencil"); DRW_render_gpencil(engine, engine->depsgraph); } } @@ -1090,6 +1095,8 @@ bool RE_engine_render(Render *re, bool do_all) if (type->render) { FOREACH_VIEW_LAYER_TO_RENDER_BEGIN (re, view_layer_iter) { + CLOG_INFO(&LOG, 0, "Start rendering: %s, %s", re->scene->id.name + 2, view_layer_iter->name); + CLOG_INFO(&LOG, 0, "Engine: %s", engine->type->name); const bool use_grease_pencil = (view_layer_iter->layflag & SCE_LAY_GREASE_PENCIL) != 0; engine_render_view_layer(re, engine, view_layer_iter, true, use_grease_pencil); @@ -1151,6 +1158,7 @@ bool RE_engine_render(Render *re, bool do_all) #ifdef WITH_FREESTYLE if (re->r.mode & R_EDGE_FRS) { + CLOG_INFO(&LOG, 0, "Rendering freestyle"); RE_RenderFreestyleExternal(re); } #endif diff --git a/source/blender/render/intern/pipeline.cc b/source/blender/render/intern/pipeline.cc index 48c71e9f657..ce183025a2c 100644 --- a/source/blender/render/intern/pipeline.cc +++ b/source/blender/render/intern/pipeline.cc @@ -100,6 +100,10 @@ #include "render_result.h" #include "render_types.h" +#include "CLG_log.h" + +static CLG_LogRef LOG = {"render"}; + namespace path_templates = blender::bke::path_templates; /* render flow @@ -195,47 +199,24 @@ static void stats_background(void * /*arg*/, RenderStats *rs) return; } - uintptr_t mem_in_use, peak_memory; - float megs_used_memory, megs_peak_memory; - char info_time_str[32]; - - mem_in_use = MEM_get_memory_in_use(); - peak_memory = MEM_get_peak_memory(); - - megs_used_memory = (mem_in_use) / (1024.0 * 1024.0); - megs_peak_memory = (peak_memory) / (1024.0 * 1024.0); - - BLI_timecode_string_from_time_simple( - info_time_str, sizeof(info_time_str), BLI_time_now_seconds() - rs->starttime); - /* Compositor calls this from multiple threads, mutex lock to ensure we don't * get garbled output. */ static blender::Mutex mutex; std::scoped_lock lock(mutex); - char *message = BLI_sprintfN(RPT_("Fra:%d Mem:%.2fM (Peak %.2fM) | Time:%s | %s"), - rs->cfra, - megs_used_memory, - megs_peak_memory, - info_time_str, - rs->infostr); - if (!G.quiet) { - fprintf(stdout, "%s\n", message); - + CLOG_STR_INFO(&LOG, 0, rs->infostr); /* Flush stdout to be sure python callbacks are printing stuff after blender. */ fflush(stdout); } /* NOTE: using G_MAIN seems valid here??? * Not sure it's actually even used anyway, we could as well pass nullptr? */ - BKE_callback_exec_string(G_MAIN, BKE_CB_EVT_RENDER_STATS, message); + BKE_callback_exec_string(G_MAIN, BKE_CB_EVT_RENDER_STATS, rs->infostr); if (!G.quiet) { fflush(stdout); } - - MEM_freeN(message); } void RE_ReferenceRenderResult(RenderResult *rr) @@ -1383,6 +1364,7 @@ static void do_render_compositor(Render *re) blender::compositor::OutputTypes::Previews; } + CLOG_STR_INFO(&LOG, 0, "Executing compositor"); blender::compositor::RenderContext compositor_render_context; LISTBASE_FOREACH (RenderView *, rv, &re->result->views) { COM_execute(re, @@ -1525,6 +1507,8 @@ static void do_render_sequencer(Render *re) int view_id, tot_views; int re_x, re_y; + CLOG_STR_INFO(&LOG, 0, "Executing sequencer"); + re->i.cfra = cfra; recurs_depth++; @@ -2365,7 +2349,7 @@ static bool do_write_image_or_movie( } if (!G.quiet) { - printf("%s\n", message.c_str()); + CLOG_STR_INFO(&LOG, 0, message.c_str()); /* Flush stdout to be sure python callbacks are printing stuff after blender. */ fflush(stdout); } @@ -2375,7 +2359,6 @@ static bool do_write_image_or_movie( render_callback_exec_string(re, G_MAIN, BKE_CB_EVT_RENDER_STATS, message.c_str()); if (!G.quiet) { - fputc('\n', stdout); fflush(stdout); } @@ -2423,6 +2406,13 @@ void RE_RenderAnim(Render *re, int efra, int tfra) { + if (sfra == efra) { + CLOG_INFO(&LOG, 0, "Rendering single frame (frame %d)", sfra); + } + else { + CLOG_INFO(&LOG, 0, "Rendering animation (frames %d..%d)", sfra, efra); + } + /* Call hooks before taking a copy of scene->r, so user can alter the render settings prior to * copying (e.g. alter the output path). */ render_callback_exec_id(re, re->main, &scene->id, BKE_CB_EVT_RENDER_INIT); diff --git a/source/creator/creator_args.cc b/source/creator/creator_args.cc index 89af7c7491f..4ef4627da18 100644 --- a/source/creator/creator_args.cc +++ b/source/creator/creator_args.cc @@ -2149,6 +2149,12 @@ static int arg_handle_extension_set(int argc, const char **argv, void *data) return 0; } +static void add_log_render_filter() +{ + const char *render_filter = "render.*"; + CLG_type_filter_include(render_filter, strlen(render_filter)); +} + static const char arg_handle_render_frame_doc[] = "\n" "\tRender frame and save it.\n" @@ -2163,6 +2169,8 @@ static int arg_handle_render_frame(int argc, const char **argv, void *data) bContext *C = static_cast(data); Scene *scene = CTX_data_scene(C); if (scene) { + add_log_render_filter(); + Main *bmain = CTX_data_main(C); if (argc > 1) { @@ -2217,6 +2225,8 @@ static int arg_handle_render_animation(int /*argc*/, const char ** /*argv*/, voi bContext *C = static_cast(data); Scene *scene = CTX_data_scene(C); if (scene) { + add_log_render_filter(); + Main *bmain = CTX_data_main(C); Render *re = RE_NewSceneRender(scene); ReportList reports;