From e7a21275c0f1bfb0e8bbeda384e5b46131e48b93 Mon Sep 17 00:00:00 2001
From: Aras Pranckevicius <aras@nesnausk.org>
Date: Fri, 1 Jul 2022 12:17:50 +0300
Subject: IO: print import & export times of Alembic & USD
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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
---
 source/blender/io/usd/intern/usd_capi_export.cc | 12 ++++++++++++
 source/blender/io/usd/intern/usd_capi_import.cc | 12 ++++++++++++
 2 files changed, 24 insertions(+)

(limited to 'source/blender/io/usd/intern')

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)
-- 
cgit v1.2.3