Commit: e7a21275c0f1bfb0e8bbeda384e5b46131e48b93 Author: Aras Pranckevicius Date: Fri Jul 1 12:17:50 2022 +0300 Branches: master https://developer.blender.org/rBe7a21275c0f1bfb0e8bbeda384e5b46131e48b93
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 =================================================================== M source/blender/blenlib/intern/timeit.cc M source/blender/io/alembic/exporter/abc_export_capi.cc M source/blender/io/alembic/intern/alembic_capi.cc M source/blender/io/usd/intern/usd_capi_export.cc M source/blender/io/usd/intern/usd_capi_import.cc =================================================================== 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) _______________________________________________ Bf-blender-cvs mailing list Bf-blender-cvs@blender.org List details, subscription details or unsubscribe: https://lists.blender.org/mailman/listinfo/bf-blender-cvs
