int: Additional timing logging for performance investigations (Academ…

…ySoftwareFoundation#4506) Signed-off-by: Larry Gritz <[email protected]>
lgritz · Oct 26, 2024 · 7e7dc0e · 7e7dc0e
1 parent 8e78a3d
commit 7e7dc0e
Show file tree

Hide file tree

Showing 5 changed files with 14 additions and 1 deletion.
diff --git a/src/libOpenImageIO/imagebuf.cpp b/src/libOpenImageIO/imagebuf.cpp
@@ -1045,6 +1045,8 @@ ImageBufImpl::init_spec(string_view filename, int subimage, int miplevel,
         && m_current_subimage == subimage && m_current_miplevel == miplevel)
         return true;  // Already done
 
+    pvt::LoggedTimer logtime("IB::init_spec");
+
     m_name = filename;
 
     // If we weren't given an imagecache but "imagebuf:use_imagecache"
@@ -1219,6 +1221,7 @@ ImageBufImpl::read(int subimage, int miplevel, int chbegin, int chend,
         return false;
     }
 
+    pvt::LoggedTimer logtime("IB::read");
     m_current_subimage = subimage;
     m_current_miplevel = miplevel;
     if (chend < 0 || chend > nativespec().nchannels)
@@ -1465,6 +1468,7 @@ ImageBuf::write(ImageOutput* out, ProgressCallback progress_callback,
     }
     bool ok = true;
     ok &= m_impl->validate_pixels();
+    pvt::LoggedTimer("IB::write inner");
     if (out->supports("thumbnail") && has_thumbnail()) {
         auto thumb = get_thumbnail();
         // Strutil::print("IB::write: has thumbnail ROI {}\n", thumb->roi());
@@ -1581,6 +1585,7 @@ ImageBuf::write(string_view _filename, TypeDesc dtype, string_view _fileformat,
                 ProgressCallback progress_callback,
                 void* progress_callback_data) const
 {
+    pvt::LoggedTimer("IB::write");
     string_view filename   = _filename.size() ? _filename : string_view(name());
     string_view fileformat = _fileformat.size() ? _fileformat : filename;
     if (filename.size() == 0) {

diff --git a/src/libOpenImageIO/imagebufalgo_copy.cpp b/src/libOpenImageIO/imagebufalgo_copy.cpp
@@ -307,7 +307,8 @@ ImageBufAlgo::crop(const ImageBuf& src, ROI roi, int nthreads)
 bool
 ImageBufAlgo::cut(ImageBuf& dst, const ImageBuf& src, ROI roi, int nthreads)
 {
-    pvt::LoggedTimer logtime("IBA::cut");
+    // pvt::LoggedTimer logtime("IBA::cut");
+    // Don't log, because all the work is inside crop, which already logs
     bool ok = crop(dst, src, roi, nthreads);
     if (!ok)
         return false;

diff --git a/src/libOpenImageIO/imageinput.cpp b/src/libOpenImageIO/imageinput.cpp
@@ -287,6 +287,7 @@ ImageInput::read_scanlines(int subimage, int miplevel, int ybegin, int yend,
                            int z, int chbegin, int chend, TypeDesc format,
                            void* data, stride_t xstride, stride_t ystride)
 {
+    pvt::LoggedTimer logtime("II::read_scanlines");
     ImageSpec spec;
     int rps = 0;
     {
@@ -845,6 +846,7 @@ ImageInput::read_image(int subimage, int miplevel, int chbegin, int chend,
                        ProgressCallback progress_callback,
                        void* progress_callback_data)
 {
+    pvt::LoggedTimer logtime("II::read_image");
     ImageSpec spec;
     int rps = 0;
     {

diff --git a/src/libOpenImageIO/imageoutput.cpp b/src/libOpenImageIO/imageoutput.cpp
@@ -487,6 +487,7 @@ ImageOutput::write_image(TypeDesc format, const void* data, stride_t xstride,
                          ProgressCallback progress_callback,
                          void* progress_callback_data)
 {
+    pvt::LoggedTimer("ImageOutput::write image");
     bool native          = (format == TypeDesc::UNKNOWN);
     stride_t pixel_bytes = native ? (stride_t)m_spec.pixel_bytes(native)
                                   : format.size() * m_spec.nchannels;

diff --git a/src/tiff.imageio/tiffoutput.cpp b/src/tiff.imageio/tiffoutput.cpp
@@ -23,6 +23,8 @@
 #include <OpenImageIO/tiffutils.h>
 #include <OpenImageIO/timer.h>
 
+#include "imageio_pvt.h"
+
 
 // clang-format off
 #ifdef TIFFLIB_MAJOR_VERSION
@@ -1340,6 +1342,7 @@ TIFFOutput::write_scanlines(int ybegin, int yend, int z, TypeDesc format,
                             const void* data, stride_t xstride,
                             stride_t ystride)
 {
+    pvt::LoggedTimer("TIFFOutput::write_scanlines");
     // If the stars all align properly, try to write strips, and use the
     // thread pool to parallelize the compression. This can give a large
     // speedup (5x or more!) because the zip compression dwarfs the
@@ -1566,6 +1569,7 @@ TIFFOutput::write_tiles(int xbegin, int xend, int ybegin, int yend, int zbegin,
                         int zend, TypeDesc format, const void* data,
                         stride_t xstride, stride_t ystride, stride_t zstride)
 {
+    pvt::LoggedTimer("TIFFOutput::write_tiles");
     if (!m_spec.valid_tile_range(xbegin, xend, ybegin, yend, zbegin, zend))
         return false;