IO: print import & export times of Alembic & USD

Many existing importers/exporters do log the time it takes to system
console (some others log more information too). In particular, OBJ
(C++ & python), STL (C++ & python), PLY, glTF2 all log the time it
takes. However, neither USD nor Alembic do. And also it's harder to
know the time it takes there from a profiler, since all the work
normally is done on a background job and is split between several
threads (so you can't just find some top-level function and see how
much time it took).

This change:

- Adds import/export time logging to USD & Alembic importer/exporter,
- In the time utility class (also used by OBJ & STL), improve the
  output formatting: 1) print only one decimal digit, 2) for long
  times, print seconds and also produce a hours:minutes:seconds form.

Reviewed By: Michael Kowalski, Kévin Dietrich
Differential Revision: https://developer.blender.org/D15170

5 files changed, 62 insertions, 4 deletions

diff --git a/source/blender/blenlib/intern/timeit.cc b/source/blender/blenlib/intern/timeit.cc
index f11f9c4ad94..7a8cf8da038 100644
--- a/source/blender/blenlib/intern/timeit.cc
+++ b/source/blender/blenlib/intern/timeit.cc
@@ -3,19 +3,29 @@
 #include "BLI_timeit.hh"
 
 #include <algorithm>
+#include <iomanip>
 
 namespace blender::timeit {
 
 void print_duration(Nanoseconds duration)
 {
-  if (duration < std::chrono::microseconds(100)) {
+  using namespace std::chrono;
+  if (duration < microseconds(100)) {
     std::cout << duration.count() << " ns";
   }
-  else if (duration < std::chrono::seconds(5)) {
-    std::cout << duration.count() / 1.0e6 << " ms";
+  else if (duration < seconds(5)) {
+    std::cout << std::fixed << std::setprecision(1) << duration.count() / 1.0e6 << " ms";
+  }
+  else if (duration > seconds(90)) {
+    /* Long durations: print seconds, and also H:m:s */
+    const auto dur_hours = duration_cast<hours>(duration);
+    const auto dur_mins = duration_cast<minutes>(duration - dur_hours);
+    const auto dur_sec = duration_cast<seconds>(duration - dur_hours - dur_mins);
+    std::cout << std::fixed << std::setprecision(1) << duration.count() / 1.0e9 << " s ("
+              << dur_hours.count() << "H:" << dur_mins.count() << "m:" << dur_sec.count() << "s)";
   }
   else {
-    std::cout << duration.count() / 1.0e9 << " s";
+    std::cout << std::fixed << std::setprecision(1) << duration.count() / 1.0e9 << " s";
   }
 }
 
diff --git a/source/blender/io/alembic/exporter/abc_export_capi.cc b/source/blender/io/alembic/exporter/abc_export_capi.cc
index 5554fb505a4..dfca89e2c6d 100644
--- a/source/blender/io/alembic/exporter/abc_export_capi.cc
+++ b/source/blender/io/alembic/exporter/abc_export_capi.cc
@@ -24,6 +24,7 @@
 #include "BLI_fileops.h"
 #include "BLI_path_util.h"
 #include "BLI_string.h"
+#include "BLI_timeit.hh"
 
 #include "WM_api.h"
 #include "WM_types.h"
@@ -44,6 +45,7 @@ struct ExportJobData {
 
   bool was_canceled;
   bool export_ok;
+  blender::timeit::TimePoint start_time;
 };
 
 namespace blender::io::alembic {
@@ -59,6 +61,14 @@ static void build_depsgraph(Depsgraph *depsgraph, const bool visible_objects_onl
   }
 }
 
+static void report_job_duration(const ExportJobData *data)
+{
+  blender::timeit::Nanoseconds duration = blender::timeit::Clock::now() - data->start_time;
+  std::cout << "Alembic export of '" << data->filename << "' took ";
+  blender::timeit::print_duration(duration);
+  std::cout << '\n';
+}
+
 static void export_startjob(void *customdata,
                             /* Cannot be const, this function implements wm_jobs_start_callback.
                              * NOLINTNEXTLINE: readability-non-const-parameter. */
@@ -68,6 +78,7 @@ static void export_startjob(void *customdata,
 {
   ExportJobData *data = static_cast<ExportJobData *>(customdata);
   data->was_canceled = false;
+  data->start_time = blender::timeit::Clock::now();
 
   G.is_rendering = true;
   WM_set_locked_interface(data->wm, true);
@@ -177,6 +188,7 @@ static void export_endjob(void *customdata)
 
   G.is_rendering = false;
   WM_set_locked_interface(data->wm, false);
+  report_job_duration(data);
 }
 
 }  // namespace blender::io::alembic
diff --git a/source/blender/io/alembic/intern/alembic_capi.cc b/source/blender/io/alembic/intern/alembic_capi.cc
index cd6750341a8..27df23b38c6 100644
--- a/source/blender/io/alembic/intern/alembic_capi.cc
+++ b/source/blender/io/alembic/intern/alembic_capi.cc
@@ -50,6 +50,7 @@
 #include "BLI_math.h"
 #include "BLI_path_util.h"
 #include "BLI_string.h"
+#include "BLI_timeit.hh"
 
 #include "WM_api.h"
 #include "WM_types.h"
@@ -434,8 +435,17 @@ struct ImportJobData {
   bool was_cancelled;
   bool import_ok;
   bool is_background_job;
+  blender::timeit::TimePoint start_time;
 };
 
+static void report_job_duration(const ImportJobData *data)
+{
+  blender::timeit::Nanoseconds duration = blender::timeit::Clock::now() - data->start_time;
+  std::cout << "Alembic import of '" << data->filename << "' took ";
+  blender::timeit::print_duration(duration);
+  std::cout << '\n';
+}
+
 static void import_startjob(void *user_data, short *stop, short *do_update, float *progress)
 {
   SCOPE_TIMER("Alembic import, objects reading and creation");
@@ -445,6 +455,7 @@ static void import_startjob(void *user_data, short *stop, short *do_update, floa
   data->stop = stop;
   data->do_update = do_update;
   data->progress = progress;
+  data->start_time = blender::timeit::Clock::now();
 
   WM_set_locked_interface(data->wm, true);
 
@@ -649,6 +660,7 @@ static void import_endjob(void *user_data)
   }
 
   WM_main_add_notifier(NC_SCENE | ND_FRAME, data->scene);
+  report_job_duration(data);
 }
 
 static void import_freejob(void *user_data)
diff --git a/source/blender/io/usd/intern/usd_capi_export.cc b/source/blender/io/usd/intern/usd_capi_export.cc
index d9995117b70..1033f85181c 100644
--- a/source/blender/io/usd/intern/usd_capi_export.cc
+++ b/source/blender/io/usd/intern/usd_capi_export.cc
@@ -27,6 +27,7 @@
 #include "BLI_fileops.h"
 #include "BLI_path_util.h"
 #include "BLI_string.h"
+#include "BLI_timeit.hh"
 
 #include "WM_api.h"
 #include "WM_types.h"
@@ -42,8 +43,17 @@ struct ExportJobData {
   USDExportParams params;
 
   bool export_ok;
+  timeit::TimePoint start_time;
 };
 
+static void report_job_duration(const ExportJobData *data)
+{
+  timeit::Nanoseconds duration = timeit::Clock::now() - data->start_time;
+  std::cout << "USD export of '" << data->filepath << "' took ";
+  timeit::print_duration(duration);
+  std::cout << '\n';
+}
+
 static void export_startjob(void *customdata,
                             /* Cannot be const, this function implements wm_jobs_start_callback.
                              * NOLINTNEXTLINE: readability-non-const-parameter. */
@@ -53,6 +63,7 @@ static void export_startjob(void *customdata,
 {
   ExportJobData *data = static_cast<ExportJobData *>(customdata);
   data->export_ok = false;
+  data->start_time = timeit::Clock::now();
 
   G.is_rendering = true;
   WM_set_locked_interface(data->wm, true);
@@ -151,6 +162,7 @@ static void export_endjob(void *customdata)
 
   G.is_rendering = false;
   WM_set_locked_interface(data->wm, false);
+  report_job_duration(data);
 }
 
 }  // namespace blender::io::usd
diff --git a/source/blender/io/usd/intern/usd_capi_import.cc b/source/blender/io/usd/intern/usd_capi_import.cc
index 4118205d87f..13ae6f4d4c0 100644
--- a/source/blender/io/usd/intern/usd_capi_import.cc
+++ b/source/blender/io/usd/intern/usd_capi_import.cc
@@ -30,6 +30,7 @@
 #include "BLI_math_rotation.h"
 #include "BLI_path_util.h"
 #include "BLI_string.h"
+#include "BLI_timeit.hh"
 
 #include "DEG_depsgraph.h"
 #include "DEG_depsgraph_build.h"
@@ -132,8 +133,17 @@ struct ImportJobData {
   char error_code;
   bool was_canceled;
   bool import_ok;
+  timeit::TimePoint start_time;
 };
 
+static void report_job_duration(const ImportJobData *data)
+{
+  timeit::Nanoseconds duration = timeit::Clock::now() - data->start_time;
+  std::cout << "USD import of '" << data->filepath << "' took ";
+  timeit::print_duration(duration);
+  std::cout << '\n';
+}
+
 static void import_startjob(void *customdata, short *stop, short *do_update, float *progress)
 {
   ImportJobData *data = static_cast<ImportJobData *>(customdata);
@@ -143,6 +153,7 @@ static void import_startjob(void *customdata, short *stop, short *do_update, flo
   data->progress = progress;
   data->was_canceled = false;
   data->archive = nullptr;
+  data->start_time = timeit::Clock::now();
 
   WM_set_locked_interface(data->wm, true);
   G.is_break = false;
@@ -337,6 +348,7 @@ static void import_endjob(void *customdata)
   }
 
   WM_main_add_notifier(NC_SCENE | ND_FRAME, data->scene);
+  report_job_duration(data);
 }
 
 static void import_freejob(void *user_data)