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

1 files changed, 12 insertions, 0 deletions

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)