From 4ff01cce6c7ba9cc68a5e1e36525b608c0a628d9 Mon Sep 17 00:00:00 2001
From: Robbert van der Helm <mail@robbertvanderhelm.nl>
Date: Wed, 9 Jun 2021 23:13:40 +0200
Subject: [PATCH] Report the mean and max VST3 audio processing time

Every five seconds.
---
 .../bridges/vst3-impls/plugin-proxy.cpp       | 53 ++++++++++++++++++-
 src/plugin/bridges/vst3-impls/plugin-proxy.h  | 22 ++++++++
 2 files changed, 74 insertions(+), 1 deletion(-)

diff --git a/src/plugin/bridges/vst3-impls/plugin-proxy.cpp b/src/plugin/bridges/vst3-impls/plugin-proxy.cpp
index 29cb176a..37ffdd9c 100644
--- a/src/plugin/bridges/vst3-impls/plugin-proxy.cpp
+++ b/src/plugin/bridges/vst3-impls/plugin-proxy.cpp
@@ -18,6 +18,8 @@
 
 #include "plug-view-proxy.h"
 
+using namespace std::literals::chrono_literals;
+
 /**
  * When the host tries to connect two plugin instances with connection proxies,
  * we'll first try to bypass that proxy. This goes against the idea of yabridge,
@@ -35,13 +37,20 @@ constexpr char other_instance_message_id[] = "yabridge_other_instance";
  */
 constexpr char other_instance_pointer_attribute[] = "other_proxy_ptr";
 
+/**
+ * The time between reports for the mean processing time.
+ */
+constexpr std::chrono::high_resolution_clock::duration report_interval = 5s;
+
 Vst3PluginProxyImpl::ContextMenu::ContextMenu(
     Steinberg::IPtr<Steinberg::Vst::IContextMenu> menu)
     : menu(menu) {}
 
 Vst3PluginProxyImpl::Vst3PluginProxyImpl(Vst3PluginBridge& bridge,
                                          Vst3PluginProxy::ConstructArgs&& args)
-    : Vst3PluginProxy(std::move(args)), bridge(bridge) {
+    : Vst3PluginProxy(std::move(args)),
+      bridge(bridge),
+      last_report(std::chrono::high_resolution_clock::now()) {
     bridge.register_plugin_proxy(*this);
 }
 
@@ -218,6 +227,35 @@ tresult PLUGIN_API Vst3PluginProxyImpl::setProcessing(TBool state) {
 
 tresult PLUGIN_API
 Vst3PluginProxyImpl::process(Steinberg::Vst::ProcessData& data) {
+    if (const auto& now = std::chrono::high_resolution_clock::now();
+        now - last_report >= report_interval) {
+        bridge.logger.log(
+            "Mean processing time: " +
+            std::to_string(
+                std::chrono::duration_cast<
+                    std::chrono::duration<float, std::micro>>(mean_process_time)
+                    .count()) +
+            " us");
+
+        // As mentioned below, we'll only record the maximum after the first
+        // report
+        bridge.logger.log(
+            "Max processing time:  " +
+            (have_reported
+                 ? std::to_string(std::chrono::duration_cast<
+                                      std::chrono::duration<float, std::micro>>(
+                                      max_process_time)
+                                      .count()) +
+                       " us"
+                 : "<still warming up>"));
+
+        last_report = now;
+        have_reported = true;
+    }
+
+    // Doing this twice is a bit of a waste, but we don't want to measure IO
+    const auto& process_start = std::chrono::high_resolution_clock::now();
+
     // We'll synchronize the scheduling priority of the audio thread on the Wine
     // plugin host with that of the host's audio thread every once in a while
     std::optional<int> new_realtime_priority = std::nullopt;
@@ -262,6 +300,19 @@ Vst3PluginProxyImpl::process(Steinberg::Vst::ProcessData& data) {
     // changes and events
     process_request.data.write_back_outputs(data, *process_buffers);
 
+    const auto& process_end = std::chrono::high_resolution_clock::now();
+    const auto& process_time = process_end - process_start;
+    mean_process_time = std::chrono::duration_cast<
+        std::chrono::high_resolution_clock::duration>(
+        (process_time * 0.05) + (mean_process_time * 0.95));
+
+    // With the current implementation we may need to resize our buffers in the
+    // first call, so we'll give ourselves a bit of a grace period to allow the
+    // buffers to warm up
+    if (have_reported) {
+        max_process_time = std::max(process_time, max_process_time);
+    }
+
     return process_response.result;
 }
 
diff --git a/src/plugin/bridges/vst3-impls/plugin-proxy.h b/src/plugin/bridges/vst3-impls/plugin-proxy.h
index 47db1806..747de6b4 100644
--- a/src/plugin/bridges/vst3-impls/plugin-proxy.h
+++ b/src/plugin/bridges/vst3-impls/plugin-proxy.h
@@ -548,4 +548,26 @@ class Vst3PluginProxyImpl : public Vst3PluginProxy {
      */
     FunctionResultCache function_result_cache;
     std::mutex function_result_cache_mutex;
+
+    /**
+     * A moving average for the time it takes to call
+     * `YaAudioProcessor::process()`.
+     */
+    std::chrono::high_resolution_clock::duration mean_process_time =
+        std::chrono::high_resolution_clock::duration::zero();
+    /**
+     * The maximum time it took to handle `YaAudioProcessor::process()`.
+     */
+    std::chrono::high_resolution_clock::duration max_process_time =
+        std::chrono::high_resolution_clock::duration::zero();
+
+    /**
+     * The last time we reported the mean processing time.
+     */
+    std::chrono::high_resolution_clock::time_point last_report;
+    /**
+     * We'll wait with reporting the maximum processing time until the first
+     * report to allow buffers to warm up.
+     */
+    bool have_reported = false;
 };