Merge branch 'Timing'

CMakeLists.txt

@@ -24,6 +24,11 @@ SET(ICET_LIBRARY_DIR ${LIBRARY_OUTPUT_PATH})
 SET(ICET_EXECUTABLE_DIR ${EXECUTABLE_OUTPUT_PATH})
 SET(C_TEST_PATH ${EXECUTABLE_OUTPUT_PATH})
 
+SET(CMAKE_MODULE_PATH
+  ${CMAKE_MODULE_PATH}
+  ${CMAKE_SOURCE_DIR}/cmake
+  )
+
 # Turn shared libraries on or off.
 OPTION(BUILD_SHARED_LIBS "Build IceT with shared libraries." OFF)
 SET(ICET_BUILD_SHARED_LIBS ${BUILD_SHARED_LIBS})
@@ -47,6 +52,12 @@ IF (NOT ${ICET_MAGIC_K} GREATER 1)
   MESSAGE(SEND_ERROR "ICET_MAGIC_K must be set to a number greater than 1.")
 ENDIF (NOT ${ICET_MAGIC_K} GREATER 1)
 
+# Configure MPE support
+IF (ICET_USE_MPI)
+  OPTION(ICET_USE_MPE "Use MPE to trace MPI communications.  This is helpful for developers trying to measure the performance of parallel compositing algorithms." OFF)
+  MARK_AS_ADVANCED(ICET_USE_MPE)
+ENDIF (ICET_USE_MPI)
+
 # Configure testing support.
 INCLUDE(Dart)
 IF (BUILD_TESTING)
@@ -115,6 +126,12 @@ IF (ICET_USE_MPI)
   MARK_AS_ADVANCED(ICET_MPI_MAX_NUMPROCS)
   SEPARATE_ARGUMENTS(ICET_MPI_PREFLAGS)
   SEPARATE_ARGUMENTS(ICET_MPI_POSTFLAGS)
+
+  IF (ICET_USE_MPE)
+    FIND_PACKAGE(MPE REQUIRED)
+    INCLUDE_DIRECTORIES(${MPE_LOG_INCLUDE_PATH})
+    SET(ICET_MPI_LIBRARIES ${MPE_LOG_LIBRARIES} ${ICET_MPI_LIBRARIES})
+  ENDIF (ICET_USE_MPE)
 ENDIF (ICET_USE_MPI)
 
 # Add extra warnings when possible.  The IceT build should be clean.  I expect

cmake/FindMPE.cmake

+# - Multi-Processing Environment (MPE) module.
+#
+# The Multi-Processing Environment (MPE) is an extention to MPI that
+# provides programmers with a suite of performance analysis tools for
+# their MPI programs.  These tools include a set of profiling libraries,
+# a set of utility programs, and a set of graphical tools.  This module
+# helps you find the libraries and includes.
+#
+# This module will set the following variables:
+# MPE_FOUND             TRUE if we have found MPE
+# MPE_LOG_COMPILE_FLAGS Compilation flags for MPI logging with MPE.
+# MPE_LOG_INCLUDE_PATH  Include path(s) for MPI logging with MPE.
+# MPE_LOG_LINK_FLAGS    Linking flags for MPI logging with MPE.
+# MPE_LOG_LIBRARIES     Libraries to link against for MPI logging with MPE.
+#
+# This module will auto-detect these setting by looking for an MPE
+# compiler (mpecc) and use the -show flag to retrieve compiler options.
+#
+# Note that this module does not attempt to ensure that the version
+# of MPE you are using is compatible with the version of MPI that
+# you are using (or even that you are using MPI at all).
+#
+
+## Copyright 2011 Sandia Coporation
+## Under the terms of Contract DE-AC04-94AL85000 with Sandia Corporation,
+## the U.S. Government retains certain rights in this software.
+##
+## This source code is released under the New BSD License.
+#
+
+find_program(MPE_COMPILER
+  NAMES mpecc
+  DOC "MPE compiler.  Used only to detect MPE compilation flags."
+  )
+
+if (MPE_LOG_INCLUDE_PATH AND MPE_LOG_LIBRARIES)
+  # Do nothing: we already have the necessary options.
+elseif (MPE_COMPILER)
+  exec_program(${MPE_COMPILER}
+    ARGS -show -mpilog
+    OUTPUT_VARIABLE MPE_LOG_COMPILE_CMDLINE
+    RETURN_VALUE MPE_LOG_COMPILE_RETURN
+    )
+  if (NOT MPE_LOG_COMPILE_RETURN EQUAL 0)
+    message(STATUS, "Unable to determine MPE from MPE driver ${MPE_COMPILER}")
+  endif (NOT MPE_LOG_COMPILE_RETURN EQUAL 0)
+endif (MPE_LOG_INCLUDE_PATH AND MPE_LOG_LIBRARIES)
+
+if (MPE_LOG_INCLUDE_PATH AND MPE_LOG_LIBRARIES)
+elseif (MPE_LOG_COMPILE_CMDLINE)
+  # Extract compile flags from the compile command line.
+  string(REGEX MATCHALL "-D([^\" ]+|\"[^\"]+\")"
+    MPE_ALL_COMPILE_FLAGS
+    "${MPE_LOG_COMPILE_CMDLINE}")
+  set(MPE_COMPILE_FLAGS_WORK)
+  foreach(FLAG ${MPE_ALL_COMPILE_FLAGS})
+    if (MPE_COMPILE_FLAGS_WORK)
+      set(MPE_COMPILE_FLAGS_WORK "${MPE_COMPILE_FLAGS_WORK} ${FLAG}")
+    else(MPE_COMPILE_FLAGS_WORK)
+      set(MPE_COMPILE_FLAGS_WORK ${FLAG})
+    endif(MPE_COMPILE_FLAGS_WORK)
+  endforeach(FLAG)
+
+  # Extract include paths from compile command line
+  string(REGEX MATCHALL "-I([^\" ]+|\"[^\"]+\")"
+    MPE_ALL_INCLUDE_PATHS
+    "${MPE_LOG_COMPILE_CMDLINE}")
+  set(MPE_INCLUDE_PATH_WORK)
+  foreach(IPATH ${MPE_ALL_INCLUDE_PATHS})
+    string(REGEX REPLACE "^-I" "" IPATH ${IPATH})
+    string(REGEX REPLACE "//" "/" IPATH ${IPATH})
+    list(APPEND MPE_INCLUDE_PATH_WORK ${IPATH})
+  endforeach(IPATH)
+
+  # Extract linker paths from the link command line
+  string(REGEX MATCHALL "-L([^\" ]+|\"[^\"]+\")"
+    MPE_ALL_LINK_PATHS
+    "${MPE_LOG_COMPILE_CMDLINE}")
+  set(MPE_LINK_PATH)
+  foreach(LPATH ${MPE_ALL_LINK_PATHS})
+    string(REGEX REPLACE "^-L" "" LPATH ${LPATH})
+    string(REGEX REPLACE "//" "/" LPATH ${LPATH})
+    list(APPEND MPE_LINK_PATH ${LPATH})
+  endforeach(LPATH)
+
+  # Extract linker flags from the link command line
+  string(REGEX MATCHALL "-Wl,([^\" ]+|\"[^\"]+\")"
+    MPE_ALL_LINK_FLAGS
+    "${MPE_LOG_COMPILE_CMDLINE}")
+  set(MPE_LINK_FLAGS_WORK)
+  foreach(FLAG ${MPE_ALL_LINK_FLAGS})
+    if (MPE_LINK_FLAGS_WORK)
+      set(MPE_LINK_FLAGS_WORK "${MPE_LINK_FLAGS_WORK} ${FLAG}")
+    else(MPE_LINK_FLAGS_WORK)
+      set(MPE_LINK_FLAGS_WORK ${FLAG})
+    endif(MPE_LINK_FLAGS_WORK)
+  endforeach(FLAG)
+
+  # Extract the set of libraries to link against from the link command
+  # line
+  string(REGEX MATCHALL "-l([^\" ]+|\"[^\"]+\")"
+    MPE_LOG_LIBNAMES
+    "${MPE_LOG_COMPILE_CMDLINE}")
+
+  # Determine full path names for all of the libraries that one needs
+  # to link against in an MPI program
+  set(MPE_LIBRARIES_WORK)
+  foreach(LIB ${MPE_LOG_LIBNAMES})
+    string(REGEX REPLACE "^-l" "" LIB ${LIB})
+    set(MPE_LIB "MPE_LIB-NOTFOUND" CACHE FILEPATH "Cleared" FORCE)
+    find_library(MPE_LIB ${LIB} HINTS ${MPE_LINK_PATH})
+    if (MPE_LIB)
+      list(APPEND MPE_LIBRARIES_WORK ${MPE_LIB})
+    else (MPE_LIB)
+      message(SEND_ERROR "Unable to find MPE library ${LIB}")
+    endif (MPE_LIB)
+  endforeach(LIB)
+  set(MPE_LIB "MPE_LIB-NOTFOUND"
+    CACHE INTERNAL "Scratch variable for MPI detection" FORCE)
+
+  # Set up all of the appropriate cache entries
+  set(MPE_LOG_COMPILE_FLAGS ${MPE_COMPILE_FLAGS_WORK}
+    CACHE STRING "MPE log compilation flags" FORCE)
+  set(MPE_LOG_INCLUDE_PATH ${MPE_INCLUDE_PATH_WORK}
+    CACHE STRING "MPE log include path" FORCE)
+  set(MPE_LOG_LINK_FLAGS ${MPE_LINK_FLAGS_WORK}
+    CACHE STRING "MPE log linking flags" FORCE)
+  set(MPE_LOG_LIBRARIES ${MPE_LIBRARIES_WORK}
+    CACHE PATH "MPE log libraries" FORCE)
+endif (MPE_LOG_INCLUDE_PATH AND MPE_LOG_LIBRARIES)
+
+if (MPE_LOG_INCLUDE_PATH AND MPE_LOG_LIBRARIES)
+  set(MPE_FOUND TRUE)
+else (MPE_LOG_INCLUDE_PATH AND MPE_LOG_LIBRARIES)
+  set(MPE_FOUND FALSE)
+endif (MPE_LOG_INCLUDE_PATH AND MPE_LOG_LIBRARIES)
+
+include(FindPackageHandleStandardArgs)
+# handle the QUIETLY and REQUIRED arguments
+find_package_handle_standard_args(
+  MPE
+  DEFAULT_MSG
+  MPE_LOG_LIBRARIES
+  MPE_LOG_INCLUDE_PATH
+  )
+
+mark_as_advanced(
+  MPE_LOG_COMPILE_FLAGS
+  MPE_LOG_INCLUDE_PATH
+  MPE_LOG_LINK_FLAGS
+  MPE_LOG_LIBRARIES
+  MPE_COMPILER
+  )

src/gl/gl_draw.c

@@ -11,6 +11,7 @@
 
 #include <IceTDevDiagnostics.h>
 #include <IceTDevState.h>
+#include <IceTDevTiming.h>
 
 #include <IceTDevGLImage.h>
 
@@ -139,7 +140,8 @@ static void finalizeOpenGLRender(const IceTImage image,
                                  IceTDrawCallbackType original_callback)
 {
     IceTInt display_tile;
-    IceTDouble buf_write_time;
+
+    icetTimingBufferWriteBegin();
 
   /* Restore core IceT callback. */
     icetDrawCallback(original_callback);
@@ -150,7 +152,6 @@ static void finalizeOpenGLRender(const IceTImage image,
 
   /* Paste final image back to buffer if enabled. */
     icetGetIntegerv(ICET_TILE_DISPLAYED, &display_tile);
-    buf_write_time = icetWallTime();
     if (display_tile >= 0) {
         IceTEnum color_format = icetImageGetColorFormat(image);
 
@@ -168,8 +169,7 @@ static void finalizeOpenGLRender(const IceTImage image,
     glLoadMatrixd(modelview_matrix);
 
   /* Calculate display times. */
-    buf_write_time = icetWallTime() - buf_write_time;
-    icetStateSetDouble(ICET_BUFFER_WRITE_TIME, buf_write_time);
+    icetTimingBufferWriteEnd();
 }
 
 static void correctOpenGLRenderTimes(IceTDouble total_time)

src/gl/gl_image.c

@@ -13,6 +13,7 @@
 
 #include <IceTDevDiagnostics.h>
 #include <IceTDevState.h>
+#include <IceTDevTiming.h>
 
 void icetGLDrawCallbackFunction(const IceTDouble *projection_matrix,
                                 const IceTDouble *modelview_matrix,
@@ -56,6 +57,11 @@ void icetGLDrawCallbackFunction(const IceTDouble *projection_matrix,
         (*callback)();
     }
 
+    /* Temporarily stop render time while reading back buffer. */
+    icetTimingRenderEnd();
+
+    icetTimingBufferReadBegin();
+
   /* Read the OpenGL buffers. */
     {
         IceTEnum color_format = icetImageGetColorFormat(result);
@@ -63,9 +69,6 @@ void icetGLDrawCallbackFunction(const IceTDouble *projection_matrix,
         IceTEnum readbuffer;
         IceTSizeType x_offset = gl_viewport[0] + readback_viewport[0];
         IceTSizeType y_offset = gl_viewport[1] + readback_viewport[1];
-        IceTDouble read_time;
-        IceTDouble render_time;
-        IceTDouble timer;
 
         glPixelStorei(GL_PACK_ROW_LENGTH, (GLint)icetImageGetWidth(result));
 
@@ -78,8 +81,6 @@ void icetGLDrawCallbackFunction(const IceTDouble *projection_matrix,
         icetGetEnumv(ICET_GL_READ_BUFFER, &readbuffer);
         glReadBuffer(readbuffer);
 
-        timer = icetWallTime();
-
         if (color_format == ICET_IMAGE_COLOR_RGBA_UBYTE) {
             IceTUInt *colorBuffer = icetImageGetColorui(result);
             glReadPixels((GLint)x_offset,
@@ -121,15 +122,11 @@ void icetGLDrawCallbackFunction(const IceTDouble *projection_matrix,
         glPixelStorei(GL_PACK_ROW_LENGTH, 0);
         /* glPixelStorei(GL_PACK_SKIP_PIXELS, 0); */
         /* glPixelStorei(GL_PACK_SKIP_ROWS, 0); */
+    }
 
-        icetGetDoublev(ICET_BUFFER_READ_TIME, &read_time);
-        read_time += icetWallTime() - timer;
-        icetStateSetDouble(ICET_BUFFER_READ_TIME, read_time);
+    icetTimingBufferReadEnd();
 
-      /* Subtract read time from render time since the render time is being
-         recorded as we are in this funtion. */
-        icetGetDoublev(ICET_RENDER_TIME, &render_time);
-        render_time -= read_time;
-        icetStateSetDouble(ICET_RENDER_TIME, render_time);
-    }
+    /* Start render timer again.  It's going to be shut off immediately on
+       return anyway, but the calling function expects it to be running. */
+    icetTimingRenderBegin();
 }

src/ice-t/CMakeLists.txt

@@ -12,6 +12,7 @@ SET(ICET_SRCS
         diagnostics.c
         communication.c
         tiles.c
+	timing.c
         matrix.c
         projections.c
         draw.c

src/ice-t/compress_template_body.h

@@ -74,12 +74,9 @@
 #ifdef DEBUG
     IceTSizeType _totalcount = 0;
 #endif
-    IceTDouble _timer;
-    IceTDouble _compress_time;
     IceTSizeType _compressed_size;
 
-    icetGetDoublev(ICET_COMPRESS_TIME, &_compress_time);
-    _timer = icetWallTime();
+    icetTimingCompressBegin();
 
     _dest = ICET_IMAGE_DATA(CT_COMPRESSED_IMAGE);
 
@@ -220,8 +217,7 @@
     }
 #endif /*DEBUG*/
 
-    _compress_time += icetWallTime() - _timer;
-    icetStateSetDouble(ICET_COMPRESS_TIME, _compress_time);
+    icetTimingCompressEnd();
 
     _compressed_size
         = (IceTSizeType)

src/ice-t/decompress_func_body.h

@@ -61,12 +61,9 @@
     IceTEnum _color_format, _depth_format;
     IceTSizeType _pixel_count;
     IceTEnum _composite_mode;
-#ifdef TIME_DECOMPRESSION
-    IceTDouble _timer;
-    IceTDouble _compress_time;
 
-    icetGetDoublev(ICET_COMPRESS_TIME, &_compress_time);
-    _timer = icetWallTime();
+#ifdef TIME_DECOMPRESSION
+    icetTimingCompressBegin();
 #endif /* TIME_DECOMPRESSION */
 
     icetGetEnumv(ICET_COMPOSITE_MODE, &_composite_mode);
@@ -330,8 +327,7 @@
     }
 
 #ifdef TIME_DECOMPRESSION
-    _compress_time += icetWallTime() - _timer;
-    icetStateSetDouble(ICET_COMPRESS_TIME, _compress_time);
+    icetTimingCompressEnd();
 #endif
 }
 

src/ice-t/draw.c

@@ -15,6 +15,7 @@
 #include <IceTDevMatrix.h>
 #include <IceTDevState.h>
 #include <IceTDevStrategySelect.h>
+#include <IceTDevTiming.h>
 
 #include <stdlib.h>
 #include <string.h>
@@ -714,12 +715,10 @@ static void drawCorrectBackground(IceTImage image,
                                   const IceTFloat *background_color,
                                   IceTUInt background_color_word)
 {
-    IceTSizeType pixels =icetImageGetWidth(image)*icetImageGetHeight(image);
+    IceTSizeType pixels = icetImageGetWidth(image)*icetImageGetHeight(image);
     IceTEnum color_format = icetImageGetColorFormat(image);
-    IceTDouble blend_time;
 
-    icetGetDoublev(ICET_BLEND_TIME, &blend_time);
-    blend_time = icetWallTime() - blend_time;
+    icetTimingBlendBegin();
 
     if (color_format == ICET_IMAGE_COLOR_RGBA_UBYTE) {
         IceTUByte *color = icetImageGetColorub(image);
@@ -739,8 +738,7 @@ static void drawCorrectBackground(IceTImage image,
                        " with color blending.", ICET_SANITY_CHECK_FAIL);
     }
 
-    blend_time = icetWallTime() - blend_time;
-    icetStateSetDouble(ICET_BLEND_TIME, blend_time);
+    icetTimingBlendEnd();
 }
 
 IceTImage icetDrawFrame(const IceTDouble *projection_matrix,
@@ -769,7 +767,7 @@ IceTImage icetDrawFrame(const IceTDouble *projection_matrix,
     }
 
     icetStateResetTiming();
-    total_time = icetWallTime();
+    icetTimingDrawFrameBegin();
 
     icetStateSetDoublev(ICET_PROJECTION_MATRIX, 16, projection_matrix);
     icetStateSetDoublev(ICET_MODELVIEW_MATRIX, 16, modelview_matrix);
@@ -811,8 +809,9 @@ IceTImage icetDrawFrame(const IceTDouble *projection_matrix,
     icetGetDoublev(ICET_RENDER_TIME, &render_time);
     icetGetDoublev(ICET_BUFFER_READ_TIME, &buf_read_time);
 
-    total_time = icetWallTime() - total_time;
-    icetStateSetDouble(ICET_TOTAL_DRAW_TIME, total_time);
+    icetTimingDrawFrameEnd();
+
+    icetGetDoublev(ICET_TOTAL_DRAW_TIME, &total_time);
 
     compose_time = total_time - render_time - buf_read_time;
     icetStateSetDouble(ICET_COMPOSITE_TIME, compose_time);

src/ice-t/image.c

@@ -15,6 +15,7 @@
 #include <IceTDevState.h>
 #include <IceTDevDiagnostics.h>
 #include <IceTDevMatrix.h>
+#include <IceTDevTiming.h>
 
 #include <stdlib.h>
 #include <string.h>
@@ -1592,8 +1593,6 @@ void icetGetTileImage(IceTInt tile, IceTImage image)
     const IceTInt *viewports;
     IceTSizeType width, height;
     IceTImage rendered_image;
-    IceTDouble read_time;
-    IceTDouble timer;
 
     viewports = icetUnsafeStateGetInteger(ICET_TILE_VIEWPORTS);
     width = viewports[4*tile+2];
@@ -1602,7 +1601,7 @@ void icetGetTileImage(IceTInt tile, IceTImage image)
 
     rendered_image = renderTile(tile, screen_viewport, target_viewport, image);
 
-    timer = icetWallTime();
+    icetTimingBufferReadBegin();
 
     if (icetImageEqual(rendered_image, image)) {
       /* Check to make sure the screen and target viewports are also equal. */
@@ -1621,9 +1620,7 @@ void icetGetTileImage(IceTInt tile, IceTImage image)
 
     icetImageClearAroundRegion(image, target_viewport);
 
-    icetGetDoublev(ICET_BUFFER_READ_TIME, &read_time);
-    read_time += icetWallTime() - timer;
-    icetStateSetDouble(ICET_BUFFER_READ_TIME, read_time);
+    icetTimingBufferReadEnd();
 }
 
 void icetGetCompressedTileImage(IceTInt tile, IceTSparseImage compressed_image)
@@ -1735,8 +1732,6 @@ void icetComposite(IceTImage destBuffer, const IceTImage srcBuffer,
     IceTSizeType i;
     IceTEnum composite_mode;
     IceTEnum color_format, depth_format;
-    IceTDouble timer;
-    IceTDouble compare_time;
 
     pixels = icetImageGetNumPixels(destBuffer);
     if (pixels != icetImageGetNumPixels(srcBuffer)) {
@@ -1757,8 +1752,7 @@ void icetComposite(IceTImage destBuffer, const IceTImage srcBuffer,
 
     icetGetEnumv(ICET_COMPOSITE_MODE, &composite_mode);
 
-    icetGetDoublev(ICET_COMPARE_TIME, &compare_time);
-    timer = icetWallTime();
+    icetTimingBlendBegin();
 
     if (composite_mode == ICET_COMPOSITE_MODE_Z_BUFFER) {
         if (depth_format == ICET_IMAGE_DEPTH_FLOAT) {
@@ -1849,8 +1843,7 @@ void icetComposite(IceTImage destBuffer, const IceTImage srcBuffer,
                        ICET_SANITY_CHECK_FAIL);
     }
 
-    compare_time += icetWallTime() - timer;
-    icetStateSetDouble(ICET_COMPARE_TIME, compare_time);
+    icetTimingBlendEnd();
 }
 
 void icetCompressedComposite(IceTImage destBuffer,
@@ -1869,11 +1862,7 @@ void icetCompressedSubComposite(IceTImage destBuffer,
                                 const IceTSparseImage srcBuffer,
                                 int srcOnTop)
 {
-    IceTDouble timer;
-    IceTDouble compare_time;
-
-    icetGetDoublev(ICET_COMPARE_TIME, &compare_time);
-    timer = icetWallTime();
+    icetTimingBlendBegin();
 
     if (srcOnTop) {
 #define INPUT_SPARSE_IMAGE      srcBuffer
@@ -1895,27 +1884,21 @@ void icetCompressedSubComposite(IceTImage destBuffer,
 #include "decompress_func_body.h"
     }
 
-    compare_time += icetWallTime() - timer;
-    icetStateSetDouble(ICET_COMPARE_TIME, compare_time);
+    icetTimingBlendEnd();
 }
 
 void icetCompressedCompressedComposite(const IceTSparseImage front_buffer,
                                        const IceTSparseImage back_buffer,
                                        IceTSparseImage dest_buffer)
 {
-    IceTDouble timer;
-    IceTDouble compare_time;
-
-    icetGetDoublev(ICET_COMPARE_TIME, &compare_time);
-    timer = icetWallTime();
+    icetTimingBlendBegin();
 
 #define FRONT_SPARSE_IMAGE front_buffer
 #define BACK_SPARSE_IMAGE back_buffer
 #define DEST_SPARSE_IMAGE dest_buffer
 #include "cc_composite_func_body.h"
 
-    compare_time += icetWallTime() - timer;
-    icetStateSetInteger(ICET_COMPARE_TIME, compare_time);
+    icetTimingBlendEnd();
 }
 
 static IceTImage renderTile(int tile,
@@ -1930,8 +1913,6 @@ static IceTImage renderTile(int tile,
     IceTBoolean use_floating_viewport;
     IceTDrawCallbackType drawfunc;
     IceTVoid *value;
-    IceTDouble render_time;
-    IceTDouble timer;
     IceTInt readback_viewport[4];
     IceTImage render_buffer;
     IceTDouble projection_matrix[16];
@@ -2137,12 +2118,10 @@ static IceTImage renderTile(int tile,
     icetGetPointerv(ICET_DRAW_FUNCTION, &value);
     drawfunc = (IceTDrawCallbackType)value;
     icetRaiseDebug("Calling draw function.");
-    timer = icetWallTime();
+    icetTimingRenderBegin();
     (*drawfunc)(projection_matrix, modelview_matrix, background_color,
                 readback_viewport, render_buffer);
-    icetGetDoublev(ICET_RENDER_TIME, &render_time);
-    render_time += icetWallTime() - timer;
-    icetStateSetDouble(ICET_RENDER_TIME, render_time);
+    icetTimingRenderEnd();
 
     return render_buffer;
 }

src/ice-t/state.c

@@ -15,6 +15,7 @@
 #include <IceTDevDiagnostics.h>
 #include <IceTDevPorting.h>
 #include <IceTDevStrategySelect.h>
+#include <IceTDevTiming.h>
 
 #include <stdlib.h>
 #include <stdio.h>
@@ -655,19 +656,6 @@ IceTTimeStamp icetGetTimeStamp(void)
     return current_time++;
 }
 
-void icetStateResetTiming(void)
-{
-    icetStateSetDouble(ICET_RENDER_TIME, 0.0);
-    icetStateSetDouble(ICET_BUFFER_READ_TIME, 0.0);
-    icetStateSetDouble(ICET_BUFFER_WRITE_TIME, 0.0);
-    icetStateSetDouble(ICET_COMPRESS_TIME, 0.0);
-    icetStateSetDouble(ICET_COMPARE_TIME, 0.0);
-    icetStateSetDouble(ICET_COMPOSITE_TIME, 0.0);
-    icetStateSetDouble(ICET_TOTAL_DRAW_TIME, 0.0);
-
-    icetStateSetInteger(ICET_BYTES_SENT, 0);
-}
-
 void icetStateDump(void)
 {
     IceTEnum pname;

src/ice-t/timing.c

+/* -*- c -*- *******************************************************/
+/*
+ * Copyright (C) 2011 Sandia Corporation
+ * Under the terms of Contract DE-AC04-94AL85000 with Sandia Corporation,
+ * the U.S. Government retains certain rights in this software.
+ *
+ * This source code is released under the New BSD License.
+ */
+
+#include <IceTDevTiming.h>
+
+#include <IceTDevDiagnostics.h>
+#include <IceTDevState.h>
+
+#include <stdlib.h>
+#include <stdio.h>
+
+#ifdef ICET_USE_MPE
+#include <mpe_log.h>
+
+static void icetEventBegin(IceTEnum pname);
+static void icetEventEnd(IceTEnum pname);
+
+#else
+
+#define icetEventBegin(pname)
+#define icetEventEnd(pname)
+
+#endif
+
+void icetStateResetTiming(void)
+{
+    icetStateSetDouble(ICET_RENDER_TIME, 0.0);
+    icetStateSetDouble(ICET_BUFFER_READ_TIME, 0.0);
+    icetStateSetDouble(ICET_BUFFER_WRITE_TIME, 0.0);
+    icetStateSetDouble(ICET_COMPRESS_TIME, 0.0);
+    icetStateSetDouble(ICET_BLEND_TIME, 0.0);
+    icetStateSetDouble(ICET_COMPOSITE_TIME, 0.0);
+    icetStateSetDouble(ICET_TOTAL_DRAW_TIME, 0.0);
+
+    icetStateSetInteger(ICET_DRAW_TIME_ID, 0);
+    icetStateSetInteger(ICET_SUBFUNC_TIME_ID, 0);
+
+    icetStateSetInteger(ICET_BYTES_SENT, 0);
+}
+
+static void icetTimingBegin(IceTEnum start_pname,
+                            IceTEnum id_pname,
+                            IceTEnum result_pname,
+                            const char *name)
+{
+    icetRaiseDebug1("Beginning %s", name);
+    (void)name;
+
+    icetEventBegin(result_pname);
+
+    {
+        IceTInt current_id;
+        icetGetIntegerv(id_pname, &current_id);
+        if (current_id != 0) {
+            char message[256];
+            sprintf(message,
+                    "Called start for timer 0x%x,"
+                    " but end never called for timer 0x%x",
+                    result_pname,
+                    current_id);
+            icetRaiseError(message, ICET_SANITY_CHECK_FAIL);
+        }
+    }
+
+    icetStateSetInteger(id_pname, result_pname);
+    icetStateSetDouble(start_pname, icetWallTime());
+}
+
+static void icetTimingEnd(IceTEnum start_pname,
+                          IceTEnum id_pname,
+                          IceTEnum result_pname,
+                          const char *name)
+{
+    icetRaiseDebug1("Ending %s", name);
+    (void)name;
+
+    icetEventEnd(result_pname);
+
+    {
+        IceTInt current_id;
+        icetGetIntegerv(id_pname, &current_id);