Have uniform behavior for measurements

Having uniform/standardized log formats/behaviors allow for
automation tools to be easier to implement and maintain.

As the measurements done by GFXReconstruct are performance free
and were already done on the whole replay if no frame-range was
specified, I propose to consider gfxrecon-replay as always
acquiring measurements, either on the whole replay or on the
specified frame-range.

Thus there is no need for special message/behavior depending if a
frame-range has been manually specified. That's what this commit
implements:
- A measurement file is always created if the replay has been run
successfully
- The same log message at the end of the replay is displayed, no
matter if a range has been specified or not and no matter how
much time the (potentially inexistant) load has taken

In addition, as CLOCK_MONOTONIC has an arbitrary starting point,
CLOCK_BOOTTIME start/end time have been added to the measurement
file.
Also, for measurement of CPU load, it's better to have a clock
that measures process time instead of absolute time, so
CLOCK_PROCESS_CPUTIME_ID start/end time have been added to the
measurement file.

Change-Id: I79edf334cbb7382233be7c5a3d07251294d0565f

USAGE_android.md

@@ -830,7 +830,7 @@ optional arguments:
                         case the results would include the last frame).
                         (forwarded to replay tool)
   --measurement-file DEVICE_FILE
-                        Write measurements to a file at the specified path.
+                        File in which measurements are written.
                         Default is: '/sdcard/gfxrecon-measurements.json' on
                         android and './gfxrecon-measurements.json' on desktop.
                         (forwarded to replay tool)

USAGE_desktop_Vulkan.md

@@ -699,7 +699,7 @@ Optional arguments:
               last frame in the trace it will be clamped to the frame after the last
               (so in that case the results would include the last frame).
   --measurement-file <file>
-              Write measurements to a file at the specified path.
+              File in which measurements are written.
               Default is: '/sdcard/gfxrecon-measurements.json' on android and
               './gfxrecon-measurements.json' on desktop.
   --quit-after-measurement-range

android/scripts/gfxrecon.py

@@ -112,7 +112,7 @@ def CreateReplayParser():
     parser.add_argument('--use-colorspace-fallback', action='store_true', default=False, help='Swap the swapchain color space if unsupported by replay device. Check if color space is not supported by replay device and swap to VK_COLOR_SPACE_SRGB_NONLINEAR_KHR. (forwarded to replay tool).')
     parser.add_argument('--offscreen-swapchain-frame-boundary', action='store_true', default=False, help='Should only be used with offscreen swapchain. Activates the extension VK_EXT_frame_boundary (always supported if trimming, checks for driver support otherwise) and inserts command buffer submission with VkFrameBoundaryEXT where vkQueuePresentKHR was called in the original capture. This allows preserving frames when capturing a replay that uses. offscreen swapchain. (forwarded to replay tool)')
     parser.add_argument('--mfr', '--measurement-frame-range', metavar='START-END', help='Custom framerange to measure FPS for. This range will include the start frame but not the end frame. The measurement frame range defaults to all frames except the loading frame but can be configured for any range. If the end frame is past the last frame in the trace it will be clamped to the frame after the last (so in that case the results would include the last frame). (forwarded to replay tool)')
-    parser.add_argument('--measurement-file', metavar='DEVICE_FILE', help='Write measurements to a file at the specified path. Default is: \'/sdcard/gfxrecon-measurements.json\' on android and \'./gfxrecon-measurements.json\' on desktop. (forwarded to replay tool)')
+    parser.add_argument('--measurement-file', metavar='DEVICE_FILE', help='File in which measurements are written. Default is: \'/sdcard/gfxrecon-measurements.json\' on android and \'./gfxrecon-measurements.json\' on desktop. (forwarded to replay tool)')
     parser.add_argument('--quit-after-measurement-range', action='store_true', default=False, help='If this is specified the replayer will abort when it reaches the <end_frame> specified in the --measurement-frame-range argument. (forwarded to replay tool)')
     parser.add_argument('--flush-measurement-range', action='store_true', default=False, help='If this is specified the replayer will flush and wait for all current GPU work to finish at the start and end of the measurement range. (forwarded to replay tool)')
     parser.add_argument('--flush-inside-measurement-range', action='store_true', default=False, help='If this is specified the replayer will flush and wait for all current GPU work to finish at end of each frame inside the measurement range. (forwarded to replay tool)')

framework/graphics/fps_info.cpp

@@ -26,59 +26,37 @@
 #include "util/date_time.h"
 #include "util/logging.h"
 #include "util/platform.h"
+#include "nlohmann/json.hpp"
 #include "util/json_util.h"
 
-#include "nlohmann/json.hpp"
 #include <cinttypes>
 
 GFXRECON_BEGIN_NAMESPACE(gfxrecon)
 GFXRECON_BEGIN_NAMESPACE(graphics)
 
-static double GetElapsedSeconds(uint64_t start_time, uint64_t end_time)
-{
-    return util::datetime::ConvertTimestampToSeconds(
-        util::datetime::DiffTimestamps(static_cast<int64_t>(start_time), static_cast<int64_t>(end_time)));
-}
-
-static void
-WriteFpsToConsole(const char* prefix, uint64_t start_frame, uint64_t end_frame, int64_t start_time, int64_t end_time)
-{
-    assert(end_frame >= start_frame && end_time >= start_time);
-
-    double   diff_time_sec = GetElapsedSeconds(static_cast<uint64_t>(start_time), static_cast<uint64_t>(end_time));
-    uint64_t total_frames  = (end_frame - start_frame) + 1;
-    double   fps           = (diff_time_sec > 0.0) ? (static_cast<double>(total_frames) / diff_time_sec) : 0.0;
-    GFXRECON_WRITE_CONSOLE("%s %f fps, %f seconds, %" PRIu64 " frame%s, framerange %" PRIu64 "-%" PRIu64,
-                           prefix,
-                           fps,
-                           diff_time_sec,
-                           total_frames,
-                           total_frames > 1 ? "s" : "",
-                           start_frame,
-                           end_frame);
-}
-
 FpsInfo::FpsInfo(uint64_t               measurement_start_frame,
                  uint64_t               measurement_end_frame,
-                 bool                   has_measurement_range,
                  bool                   quit_after_range,
                  bool                   flush_measurement_range,
                  bool                   flush_inside_measurement_range,
                  bool                   preload_measurement_range,
                  const std::string_view measurement_file_name,
                  bool                   quit_after_frame,
                  uint64_t               quit_frame) :
-    measurement_start_frame_(measurement_start_frame),
-    measurement_end_frame_(measurement_end_frame), measurement_start_time_(0), measurement_end_time_(0),
-    has_measurement_range_(has_measurement_range), quit_after_range_(quit_after_range),
+    start_time_(0),
+    replay_start_time_(0), replay_end_time_(0), measurement_start_time_(0), measurement_end_time_(0),
+    measurement_start_boot_time_(0), measurement_end_boot_time_(0), measurement_start_process_time_(0),
+    measurement_end_process_time_(0), replay_start_frame_(0), measurement_start_frame_(measurement_start_frame),
+    measurement_end_frame_(measurement_end_frame), quit_after_range_(quit_after_range),
     flush_measurement_range_(flush_measurement_range), flush_inside_measurement_range_(flush_inside_measurement_range),
-    started_measurement_(false), ended_measurement_(false), frame_start_time_(0), frame_durations_(),
-    measurement_file_name_(measurement_file_name), preload_measurement_range_(preload_measurement_range),
+    started_measurement_(false), ended_measurement_(false), preload_measurement_range_(preload_measurement_range),
+    measurement_file_name_(measurement_file_name), frame_start_time_(0), frame_durations_(),
     quit_after_frame_(quit_after_frame), quit_frame_(quit_frame)
 {
-    if (has_measurement_range_)
+    if (util::filepath::IsFile(measurement_file_name_))
     {
-        GFXRECON_ASSERT(!measurement_file_name_.empty());
+        // To avoid thinking an ancient file is the result of this run
+        std::remove(measurement_file_name_.c_str());
     }
 }
 
@@ -105,8 +83,11 @@ void FpsInfo::BeginFrame(uint64_t frame)
     {
         if (frame >= measurement_start_frame_)
         {
-            measurement_start_time_ = util::datetime::GetTimestamp();
-            started_measurement_    = true;
+            measurement_start_boot_time_    = util::datetime::GetBootTime();
+            measurement_start_time_         = util::datetime::GetTimestamp();
+            measurement_start_process_time_ = util::datetime::GetProcessTime();
+            started_measurement_            = true;
+            GFXRECON_WRITE_CONSOLE("================== Start timer (Frame: %llu) ==================", frame);
             frame_durations_.clear();
         }
     }
@@ -118,64 +99,16 @@ void FpsInfo::EndFrame(uint64_t frame)
 {
     if (started_measurement_ && !ended_measurement_)
     {
-        frame_durations_.push_back(util::datetime::DiffTimestamps(frame_start_time_, util::datetime::GetTimestamp()));
+        int64_t frame_end_time = util::datetime::GetTimestamp();
+        frame_durations_.push_back(util::datetime::DiffTimestamps(frame_start_time_, frame_end_time));
 
         // Measurement frame range end is non-inclusive, as opposed to trim frame range
         if (frame >= measurement_end_frame_ - 1)
         {
-            measurement_end_time_ = util::datetime::GetTimestamp();
-            ended_measurement_    = true;
-
-            // Save measurements to file
-            if (!measurement_file_name_.empty())
-            {
-                double   start_time   = util::datetime::ConvertTimestampToSeconds(measurement_start_time_);
-                double   end_time     = util::datetime::ConvertTimestampToSeconds(measurement_end_time_);
-                double   diff_time    = GetElapsedSeconds(static_cast<uint64_t>(measurement_start_time_),
-                                                     static_cast<uint64_t>(measurement_end_time_));
-                uint64_t total_frames = measurement_end_frame_ - measurement_start_frame_;
-                double   fps          = static_cast<double>(total_frames) / diff_time;
-
-                nlohmann::json file_content = { { "frame_range",
-                                                  { { "start_frame", measurement_start_frame_ },
-                                                    { "end_frame", measurement_end_frame_ },
-                                                    { "frame_count", total_frames },
-                                                    { "start_time_monotonic", start_time },
-                                                    { "end_time_monotonic", end_time },
-                                                    { "duration", diff_time },
-                                                    { "fps", fps },
-                                                    { "frame_durations", frame_durations_ } } } };
-
-                FILE*   file_pointer = nullptr;
-                int32_t result       = util::platform::FileOpen(&file_pointer, measurement_file_name_.c_str(), "w");
-                if (result == 0)
-                {
-                    const std::string json_string = file_content.dump(util::kJsonIndentWidth);
-
-                    // It either writes a fully valid file, or it doesn't write anything !
-                    if (!util::platform::FileWrite(json_string.data(), json_string.size(), file_pointer))
-                    {
-                        GFXRECON_LOG_ERROR("Failed to write to measurements file '%s'.",
-                                           measurement_file_name_.c_str());
-
-                        // Try to delete the partial file from disk using <cstdio>
-                        const int remove_result = std::remove(measurement_file_name_.c_str());
-                        if (remove_result != 0)
-                        {
-                            GFXRECON_LOG_ERROR("Failed to remove measurements file '%s' (Error %i).",
-                                               measurement_file_name_.c_str(),
-                                               remove_result);
-                        }
-                    }
-                    util::platform::FileClose(file_pointer);
-                }
-                else
-                {
-                    GFXRECON_LOG_ERROR(
-                        "Failed to open measurements file '%s' (Error %i).", measurement_file_name_.c_str(), result);
-                    GFXRECON_LOG_ERROR("%s", std::strerror(result));
-                }
-            }
+            measurement_end_boot_time_    = util::datetime::GetBootTime();
+            measurement_end_process_time_ = util::datetime::GetProcessTime();
+            measurement_end_time_         = frame_end_time;
+            ended_measurement_            = true;
         }
     }
 }
@@ -189,10 +122,14 @@ bool FpsInfo::ShouldWaitIdleAfterFrame(uint64_t frame)
 
 void FpsInfo::EndFile(uint64_t frame)
 {
+    replay_end_time_ = gfxrecon::util::datetime::GetTimestamp();
+
     if (!ended_measurement_)
     {
-        measurement_end_time_  = gfxrecon::util::datetime::GetTimestamp();
-        measurement_end_frame_ = frame;
+        measurement_end_boot_time_    = util::datetime::GetBootTime();
+        measurement_end_process_time_ = util::datetime::GetProcessTime();
+        measurement_end_time_         = replay_end_time_;
+        measurement_end_frame_        = frame;
     }
 }
 
@@ -202,41 +139,71 @@ void FpsInfo::ProcessStateEndMarker(uint64_t frame_number)
     replay_start_time_  = static_cast<uint64_t>(util::datetime::GetTimestamp());
 }
 
-void FpsInfo::LogToConsole()
+void FpsInfo::LogMeasurements()
 {
-    if (!has_measurement_range_)
+    double start_time_monotonic = util::datetime::ConvertTimestampToSeconds(measurement_start_time_);
+    double end_time_monotonic   = util::datetime::ConvertTimestampToSeconds(measurement_end_time_);
+
+    double   load_time       = util::datetime::GetElapsedSeconds(start_time_, replay_start_time_);
+    double   total_time      = util::datetime::GetElapsedSeconds(start_time_, replay_end_time_);
+    double   measured_time   = util::datetime::GetElapsedSeconds(measurement_start_time_, measurement_end_time_);
+    uint64_t measured_frames = measurement_end_frame_ - measurement_start_frame_;
+    double   measured_fps    = (measured_time > 0.0) ? static_cast<double>(measured_frames) / measured_time : 0.0;
+
+    GFXRECON_WRITE_CONSOLE("Load time:  %f seconds (frame %lu)", load_time, replay_start_frame_);
+    GFXRECON_WRITE_CONSOLE("Total time: %f seconds", total_time);
+    GFXRECON_WRITE_CONSOLE("Measured FPS: %f fps, %f seconds, %lu frame%s, 1 loop, framerange [%lu-%lu)",
+                           measured_fps,
+                           measured_time,
+                           measured_frames,
+                           measured_frames > 1 ? "s" : "",
+                           measurement_start_frame_,
+                           measurement_end_frame_);
+
+    // Save measurements to file
+
+    nlohmann::json file_content = { { "frame_range",
+                                      { { "start_frame", measurement_start_frame_ },
+                                        { "end_frame", measurement_end_frame_ },
+                                        { "frame_count", measured_frames },
+                                        { "start_time_boot", measurement_start_boot_time_ },
+                                        { "start_time_process", measurement_start_process_time_ },
+                                        { "start_time_monotonic", start_time_monotonic },
+                                        { "end_time_boot", measurement_end_boot_time_ },
+                                        { "end_time_process", measurement_end_process_time_ },
+                                        { "end_time_monotonic", end_time_monotonic },
+                                        { "duration", measured_time },
+                                        { "fps", measured_fps },
+                                        { "frame_durations", frame_durations_ } } } };
+
+    FILE*   file_pointer = nullptr;
+    int32_t result       = util::platform::FileOpen(&file_pointer, measurement_file_name_.c_str(), "w");
+    if (result == 0)
     {
-        // No measurement range or no end limit to range, include trimmed
-        // range load statistics.
+        const std::string json_string = file_content.dump(util::kJsonIndentWidth);
 
-        if (replay_start_time_ != start_time_)
+        const bool success = util::platform::FileWrite(json_string.data(), json_string.size(), file_pointer);
+        util::platform::FileClose(file_pointer);
+
+        // It either writes a fully valid file, or it doesn't write anything !
+        if (!success)
         {
-            GFXRECON_WRITE_CONSOLE("Load time:  %f seconds", GetElapsedSeconds(start_time_, replay_start_time_));
+            GFXRECON_LOG_ERROR("Failed to write to measurements file '%s'.", measurement_file_name_.c_str());
+
+            // Try to delete the partial file from disk using <cstdio>
+            const int remove_result = std::remove(measurement_file_name_.c_str());
+            if (remove_result != 0)
+            {
+                GFXRECON_LOG_ERROR("Failed to remove measurements file '%s' (Error %i).",
+                                   measurement_file_name_.c_str(),
+                                   remove_result);
+            }
         }
-        GFXRECON_WRITE_CONSOLE("Total time: %f seconds",
-                               GetElapsedSeconds(start_time_, static_cast<uint64_t>(measurement_end_time_)));
-
-        WriteFpsToConsole("Replay FPS:",
-                          static_cast<uint64_t>(replay_start_frame_),
-                          measurement_end_frame_ - 1 + static_cast<uint64_t>(replay_start_frame_) - 1,
-                          static_cast<int64_t>(replay_start_time_),
-                          measurement_end_time_);
     }
     else
     {
-        // There was a measurement range, emit only statistics about the
-        // measurement range
-        double   diff_time_sec = GetElapsedSeconds(static_cast<uint64_t>(measurement_start_time_),
-                                                 static_cast<uint64_t>(measurement_end_time_));
-        uint64_t total_frames  = measurement_end_frame_ - measurement_start_frame_;
-        double   fps           = static_cast<double>(total_frames) / diff_time_sec;
-        GFXRECON_WRITE_CONSOLE("Measurement range FPS: %f fps, %f seconds, %lu frame%s, 1 loop, framerange [%lu-%lu)",
-                               fps,
-                               diff_time_sec,
-                               total_frames,
-                               total_frames > 1 ? "s" : "",
-                               measurement_start_frame_,
-                               measurement_end_frame_);
+        GFXRECON_LOG_ERROR("Failed to open measurements file '%s' (Error %i).", measurement_file_name_.c_str(), result);
+        GFXRECON_LOG_ERROR("%s", std::strerror(result));
     }
 }
 

framework/graphics/fps_info.h

@@ -38,7 +38,6 @@ class FpsInfo
   public:
     explicit FpsInfo(uint64_t         measurement_start_frame        = 1,
                      uint64_t         measurement_end_frame          = std::numeric_limits<uint64_t>::max(),
-                     bool             has_measurement_range          = false,
                      bool             quit_after_range               = false,
                      bool             flush_measurement_range        = false,
                      bool             flush_inside_measurement_range = false,
@@ -47,7 +46,7 @@ class FpsInfo
                      bool             quit_after_frame               = false,
                      uint64_t         quit_frame                     = std::numeric_limits<uint64_t>::max());
 
-    void LogToConsole();
+    void LogMeasurements();
 
     void                   BeginFile();
     bool                   ShouldWaitIdleBeforeFrame(uint64_t file_processor_frame);
@@ -60,18 +59,25 @@ class FpsInfo
     [[nodiscard]] uint64_t ShouldPreloadFrames(uint64_t current_frame) const;
 
   private:
-    uint64_t start_time_{};
+    uint64_t start_time_;
 
-    uint64_t measurement_start_frame_;
-    uint64_t measurement_end_frame_;
+    int64_t replay_start_time_;
+    int64_t replay_end_time_;
 
     int64_t measurement_start_time_;
     int64_t measurement_end_time_;
 
-    int64_t  replay_start_time_;
+    double measurement_start_boot_time_;
+    double measurement_end_boot_time_;
+
+    double measurement_start_process_time_;
+    double measurement_end_process_time_;
+
     uint64_t replay_start_frame_;
 
-    bool has_measurement_range_;
+    uint64_t measurement_start_frame_;
+    uint64_t measurement_end_frame_;
+
     bool quit_after_range_;
     bool flush_measurement_range_;
     bool flush_inside_measurement_range_;