Option to time all IBA functions (#1885)

* Option to time all IBA functions

All ImageBufAlgo functions (for now; other functionality may be added
to logging down the line) are outfitted with optional timers to count
the number of executions and total time spent for each.

This is enabled by a new global OIIO attribute "log_times", which can be
enabled and disabled at any time (for example, to only log a certain
phase of execution of an app).

The default is 0, meaning not to log -- and I believe that when turned
off, there is no added runtime cost (except for checking the flag once
per IBA function).

The initial default can be changed with the OPENIMAGEIO_LOG_TIMES
environment variable.

When log_times is nonzero, logging will occur, with a slight increase in
runtime expense to check the times and to lock and access the map that
stores all the running totals (stored separately, indexed by name). This
extra cost is probably not significant for whole-image operations such
as IBA calls, but it would not be an especially accurate way to time
fine-grained operations that work on one or a few pixels at a time.

The global getattribute() call may be used to retrieve "timing_report",
which will return a string containing a list of all the timing totals,
alphabetized by name, like this:

    IBA::computePixelStats        2   0.003s  (avg   1.34ms)
    IBA::make_texture             1  0.074s  (avg  74.05ms)
    IBA::mul                      8   0.002s  (avg   0.30ms)
    IBA::over                    10  0.024s  (avg   2.38ms)
    IBA::resize                  20   0.240s   (avg  12.18ms)
    IBA::zero                     8   0.001s  (avg   0.08ms)

If the log_times option has a value > 1 at the time that the program
terminates, the destructor of the timing data structure will
automatically print the timing report to stdout.

So, even for a program (that uses OIIO ImageBufAlgo internally) that has
no exposed option to retrieve and print the report, you can still find
out how it's spending its time by launching as

    OPENIMAGEIO_LOG_TIMES=2 my_application

Some caveats to keep in mind:
* It's possible that in situations where one IBA function ends up
  calling another, the time could be doubled-counted.
* This measures "wall clock time", so interpret carefully in the
  presence of multithreading.

Author: lgritz

CHANGES.md

@@ -56,6 +56,13 @@ Public API changes:
     * ImageBufAlgo::colorconvert variety deprecated since 1.7.
     * ImageCache::clear, deprecated since 1.7.
     * ImageCache::add_tile variety deprecated since 1.6.
+* Global OIIO attribute "log_times" (which defaults to 0 but can be overridden
+  by setting the `OPENIMAGEIO_LOG_TIMES` environment variable), when nonzero,
+  instruments ImageBufAlgo functions to record the number of times they are
+  called and how much time they take to execute. A report of these times
+  can be retrieved as a string as the "timing_report" attribute, or it will
+  be printed to stdout automatically if the value of log_times is 2 or more
+  at the time that the application exits. #1885 (1.9.2)
 
 Performance improvements:
 * ImageBufAlgo::computePixelStats is now multithreaded and should improve by

src/doc/imageioapi.tex

@@ -999,8 +999,53 @@ \section{Miscellaneous Utilities}
 of 0 indicates that it should try to read the whole image if possible.
 \apiend
 
+\apiitem{int debug}
+\vspace{10pt}
+\index{debug}
+When nonzero, various debug messages may be printed. The default is 0 for
+release builds, 1 for {\cf DEBUG} builds, but also may be overridden by the
+{\cf OPENIMAGEIO\_DEBUG} env variable.
+\apiend
+
+\apiitem{int log_times \\
+string timing_report}
+\vspace{10pt}
+\index{log_times} \index{timing_report}
+\NEW % 1.9
+
+When the \qkw{log_times} attribute is nonzero, {\cf ImageBufAlgo} functions
+are instrumented to record the number of times they were called and the
+total amount of time spent executing them. When enabled, there is a slight
+runtime performance cost due to checking the time at the start and end of
+each of those function calls, and the locking and recording of the data
+structure that holds the log information. When the {\cf log_times} attribute
+is disabled, there is no additional performance cost.
+
+The {\cf log_times} attribute is initialized to 0, but may be overridden by
+environment variable {\cf OPENIMAGEIO_LOG_TIMES}.
+\index{OPENIMAGEIO_LOG_TIMES}
+
+The report of totals can be retrieved as the value of the
+\qkw{timing_report} attribute, which is a string and is read-only. The
+report is sorted alphabetically and for each named instrumentation region,
+prints the number of times it executed, the total runtime, and the average
+per call, like this:
+\begin{code}
+    IBA::computePixelStats        2   2.69ms  (avg   1.34ms)
+    IBA::make_texture             1  74.05ms  (avg  74.05ms)
+    IBA::mul                      8   2.42ms  (avg   0.30ms)
+    IBA::over                    10  23.82ms  (avg   2.38ms)
+    IBA::resize                  20   0.24s   (avg  12.18ms)
+    IBA::zero                     8   0.66ms  (avg   0.08ms)
+\end{code}
+
+If the value of {\cf log_times} is 2 or more when the application terminates,
+the timing report will be printed to {\cf stdout} upon exit.
 \apiend
 
+\apiend
+
+
 \apiitem{bool {\ce attribute} (string_view name, int val) \\
 bool {\ce attribute} (string_view name, float val) \\
 bool {\ce attribute} (string_view name, const char *val) \\

src/include/OpenImageIO/imagebufalgo.h

@@ -1979,7 +1979,7 @@ bool OIIO_API render_text (ImageBuf &dst, int x, int y, string_view text,
                            int shadow = 0,
                            ROI roi = ROI::All(), int nthreads = 0);
 
-// Old style (pre-1.8) -- will eventually be deprecated.
+// DEPRECATED: Old style (pre-1.8) -- will eventually be deprecated.
 bool OIIO_API render_text (ImageBuf &dst, int x, int y, string_view text,
                            int fontsize, string_view fontname,
                            const float *textcolor);

src/include/OpenImageIO/imageio.h

@@ -1278,6 +1278,12 @@ OIIO_API std::string geterror ();
 ///             The default is 0 for release builds, 1 for DEBUG builds,
 ///             but also may be overridden by the OPENIMAGEIO_DEBUG env
 ///             variable.
+///     int log_times
+///             When nonzero, various internals will record how much total
+///             time they spend in execution. If the value is >= 2, these
+///             times will be printed upon exit. Thd default is 0, but will
+///             be initialized to the value of the OPENIMAGEIO_LOG_TIMES
+///             environment variable, if it exists.
 ///     int tiff:half
 ///             When nonzero, allows TIFF to write 'half' pixel data.
 ///             N.B. Most apps may not read these correctly, but OIIO will.
@@ -1326,6 +1332,8 @@ inline bool attribute (string_view name, string_view val) {
 ///             the library. Semicolons separate the lists for formats. For
 ///             example,
 ///              "jpeg:jpeg-turbo 1.5.1;png:libpng 1.6.29;gif:gif_lib 5.1.4"
+///     string "timing_report"
+///             A string containing the report of all the log_times.
 ///     string "oiio:simd"
 ///             Comma-separated list of the SIMD-related capabilities
 ///             enabled when the OIIO library was built. For example,

src/libOpenImageIO/color_ocio.cpp

@@ -42,6 +42,7 @@
 #include <OpenImageIO/color.h>
 #include <OpenImageIO/imagebufalgo.h>
 #include <OpenImageIO/imagebufalgo_util.h>
+#include "imageio_pvt.h"
 
 #ifdef USE_OCIO
 #include <OpenColorIO/OpenColorIO.h>
@@ -1104,6 +1105,7 @@ ImageBufAlgo::colorconvert (ImageBuf &dst, const ImageBuf &src,
                             ColorConfig *colorconfig,
                             ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::colorconvert");
     if (from.empty() || from == "current") {
         from = src.spec().get_string_attribute ("oiio:Colorspace", "Linear");
     }
@@ -1129,6 +1131,8 @@ ImageBufAlgo::colorconvert (ImageBuf &dst, const ImageBuf &src,
             return false;
         }
     }
+
+    logtime.stop();   // transition to other colorconvert
     bool ok = colorconvert (dst, src, processor.get(), unpremult, roi, nthreads);
     if (ok)
         dst.specmod().attribute ("oiio:ColorSpace", to);
@@ -1266,6 +1270,7 @@ ImageBufAlgo::colorconvert (ImageBuf &dst, const ImageBuf &src,
                             const ColorProcessor* processor, bool unpremult,
                             ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::colorconvert");
     // If the processor is NULL, return false (error)
     if (!processor) {
         dst.error ("Passed NULL ColorProcessor to colorconvert() [probable application bug]");
@@ -1281,11 +1286,11 @@ ImageBufAlgo::colorconvert (ImageBuf &dst, const ImageBuf &src,
         return false;
 
     // If the processor is a no-op (and it's not an in-place conversion),
-    // use paste() to simplify the operation.
+    // use copy() to simplify the operation.
     if (processor->isNoOp()) {
         roi.chend = std::max (roi.chbegin+4, roi.chend);
-        return ImageBufAlgo::paste (dst, roi.xbegin, roi.ybegin, roi.zbegin,
-                                    roi.chbegin, src, roi, nthreads);
+        logtime.stop();  // transition to copy
+        return ImageBufAlgo::copy (dst, src, TypeUnknown, roi, nthreads);
     }
 
     if (unpremult && src.spec().alpha_channel >= 0 &&
@@ -1319,6 +1324,7 @@ ImageBufAlgo::ociolook (ImageBuf &dst, const ImageBuf &src,
                         ColorConfig *colorconfig,
                         ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::ociolook");
     if (from.empty() || from == "current") {
         from = src.spec().get_string_attribute ("oiio:Colorspace", "Linear");
     }
@@ -1346,6 +1352,8 @@ ImageBufAlgo::ociolook (ImageBuf &dst, const ImageBuf &src,
             return false;
         }
     }
+
+    logtime.stop();   // transition to colorconvert
     bool ok = colorconvert (dst, src, processor.get(), unpremult, roi, nthreads);
     if (ok)
         dst.specmod().attribute ("oiio:ColorSpace", to);
@@ -1363,6 +1371,7 @@ ImageBufAlgo::ociodisplay (ImageBuf &dst, const ImageBuf &src,
                            ColorConfig *colorconfig,
                            ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::ociodisplay");
     if (from.empty() || from == "current") {
         from = src.spec().get_string_attribute ("oiio:Colorspace", "Linear");
     }
@@ -1386,6 +1395,8 @@ ImageBufAlgo::ociodisplay (ImageBuf &dst, const ImageBuf &src,
             return false;
         }
     }
+
+    logtime.stop();   // transition to colorconvert
     bool ok = colorconvert (dst, src, processor.get(), unpremult, roi, nthreads);
     return ok;
 }
@@ -1397,6 +1408,7 @@ ImageBufAlgo::ociofiletransform (ImageBuf &dst, const ImageBuf &src,
                         string_view name, bool inverse, bool unpremult,
                         ColorConfig *colorconfig, ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::ociofiletransform");
     if (name.empty()) {
         dst.error ("Unknown filetransform name");
         return false;
@@ -1417,6 +1429,8 @@ ImageBufAlgo::ociofiletransform (ImageBuf &dst, const ImageBuf &src,
             return false;
         }
     }
+
+    logtime.stop();   // transition to colorconvert
     bool ok = colorconvert (dst, src, processor.get(), unpremult, roi, nthreads);
     if (ok)
         dst.specmod().attribute ("oiio:ColorSpace", name);

src/libOpenImageIO/imagebufalgo_addsub.cpp

@@ -43,6 +43,7 @@
 #include <OpenImageIO/imagebufalgo_util.h>
 #include <OpenImageIO/deepdata.h>
 #include <OpenImageIO/dassert.h>
+#include "imageio_pvt.h"
 
 
 
@@ -113,6 +114,7 @@ bool
 ImageBufAlgo::add (ImageBuf &dst, const ImageBuf &A, const ImageBuf &B,
                    ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::add");
     if (! IBAprep (roi, &dst, &A, &B))
         return false;
     ROI origroi = roi;
@@ -145,6 +147,7 @@ bool
 ImageBufAlgo::add (ImageBuf &dst, const ImageBuf &A, const float *b,
                    ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::add");
     if (! IBAprep (roi, &dst, &A,
                    IBAprep_CLAMP_MUTUAL_NCHANNELS | IBAprep_SUPPORT_DEEP))
         return false;
@@ -167,6 +170,7 @@ bool
 ImageBufAlgo::add (ImageBuf &dst, const ImageBuf &A, float b,
                    ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::add");
     if (! IBAprep (roi, &dst, &A,
                    IBAprep_CLAMP_MUTUAL_NCHANNELS | IBAprep_SUPPORT_DEEP))
         return false;
@@ -202,6 +206,7 @@ bool
 ImageBufAlgo::sub (ImageBuf &dst, const ImageBuf &A, const ImageBuf &B,
                    ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::sub");
     if (! IBAprep (roi, &dst, &A, &B))
         return false;
     ROI origroi = roi;
@@ -234,6 +239,7 @@ bool
 ImageBufAlgo::sub (ImageBuf &dst, const ImageBuf &A, const float *b,
                    ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::sub");
     if (! IBAprep (roi, &dst, &A,
                    IBAprep_CLAMP_MUTUAL_NCHANNELS | IBAprep_SUPPORT_DEEP))
         return false;
@@ -261,6 +267,7 @@ bool
 ImageBufAlgo::sub (ImageBuf &dst, const ImageBuf &A, float b,
                    ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::sub");
     if (! IBAprep (roi, &dst, &A,
                    IBAprep_CLAMP_MUTUAL_NCHANNELS | IBAprep_SUPPORT_DEEP))
         return false;

src/libOpenImageIO/imagebufalgo_channels.cpp

@@ -43,6 +43,7 @@
 #include <OpenImageIO/imagebufalgo_util.h>
 #include <OpenImageIO/deepdata.h>
 #include <OpenImageIO/thread.h>
+#include "imageio_pvt.h"
 
 
 
@@ -81,6 +82,7 @@ ImageBufAlgo::channels (ImageBuf &dst, const ImageBuf &src,
                         const std::string *newchannelnames,
                         bool shuffle_channel_names, int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::channels");
     // Not intended to create 0-channel images.
     if (nchannels <= 0) {
         dst.error ("%d-channel images not supported", nchannels);
@@ -229,6 +231,7 @@ ImageBufAlgo::channel_append (ImageBuf &dst, const ImageBuf &A,
                               const ImageBuf &B, ROI roi,
                               int nthreads)
 {
+    pvt::LoggedTimer logtime("IBA::channel_append");
     // If the region is not defined, set it to the union of the valid
     // regions of the two source images.
     if (! roi.defined())

src/libOpenImageIO/imagebufalgo_compare.cpp

@@ -44,7 +44,7 @@
 #include <OpenImageIO/dassert.h>
 #include <OpenImageIO/thread.h>
 #include <OpenImageIO/SHA1.h>
-
+#include "imageio_pvt.h"
 
 
 OIIO_NAMESPACE_BEGIN
@@ -187,6 +187,7 @@ bool
 ImageBufAlgo::computePixelStats (PixelStats &stats, const ImageBuf &src,
                                  ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::computePixelStats");
     if (! roi.defined())
         roi = get_roi (src.spec());
     else
@@ -318,6 +319,7 @@ ImageBufAlgo::compare (const ImageBuf &A, const ImageBuf &B,
                        ImageBufAlgo::CompareResults &result,
                        ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::compare");
     // If no ROI is defined, use the union of the data windows of the two
     // images.
     if (! roi.defined())
@@ -378,6 +380,7 @@ bool
 ImageBufAlgo::isConstantColor (const ImageBuf &src, float *color,
                                ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::isConstantColor");
     // If no ROI is defined, use the data window of src.
     if (! roi.defined())
         roi = get_roi(src.spec());
@@ -415,6 +418,7 @@ bool
 ImageBufAlgo::isConstantChannel (const ImageBuf &src, int channel, float val,
                                  ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::isConstantChannel");
     // If no ROI is defined, use the data window of src.
     if (! roi.defined())
         roi = get_roi(src.spec());
@@ -455,6 +459,7 @@ isMonochrome_ (const ImageBuf &src, ROI roi, int nthreads)
 bool
 ImageBufAlgo::isMonochrome (const ImageBuf &src, ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::isMonochrome");
     // If no ROI is defined, use the data window of src.
     if (! roi.defined())
         roi = get_roi(src.spec());
@@ -511,6 +516,7 @@ ImageBufAlgo::color_count (const ImageBuf &src, imagesize_t *count,
                            const float *eps,
                            ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::color_count");
     // If no ROI is defined, use the data window of src.
     if (! roi.defined())
         roi = get_roi(src.spec());
@@ -577,6 +583,7 @@ ImageBufAlgo::color_range_check (const ImageBuf &src, imagesize_t *lowcount,
                                  const float *low, const float *high,
                                  ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::color_range_check");
     // If no ROI is defined, use the data window of src.
     if (! roi.defined())
         roi = get_roi(src.spec());
@@ -628,6 +635,7 @@ deep_nonempty_region (const ImageBuf &src, ROI roi)
 ROI
 ImageBufAlgo::nonzero_region (const ImageBuf &src, ROI roi, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::nonzero_region");
     roi = roi_intersection (roi, src.roi());
 
     if (src.deep()) {
@@ -737,6 +745,7 @@ ImageBufAlgo::computePixelHashSHA1 (const ImageBuf &src,
                                     string_view extrainfo,
                                     ROI roi, int blocksize, int nthreads)
 {
+    pvt::LoggedTimer logtimer("IBA::computePixelHashSHA1");
     if (! roi.defined())
         roi = get_roi (src.spec());
 
@@ -834,6 +843,7 @@ ImageBufAlgo::histogram (const ImageBuf &A, int channel,
                          float min, float max, imagesize_t *submin,
                          imagesize_t *supermax, ROI roi)
 {
+    pvt::LoggedTimer logtimer("IBA::histogram");
     if (A.spec().format != TypeFloat) {
         A.error ("Unsupported pixel data format '%s'", A.spec().format);
         return false;
@@ -876,6 +886,7 @@ bool
 ImageBufAlgo::histogram_draw (ImageBuf &R,
                               const std::vector<imagesize_t> &histogram)
 {
+    pvt::LoggedTimer logtimer("IBA::histogram_draw");
     // Fail if there are no bins to draw.
     int bins = histogram.size();
     if (bins == 0) {