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

@@ -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;

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';

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 {

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;
     }

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

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 ******************** */

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

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);

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[] =
     "<frame>\n"
     "\tRender frame <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<bContext *>(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<bContext *>(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;