[Bf-blender-cvs] [6b28b777305] master: Depsgraph: Report FPS when running with --debug-depsgraph-time

[Sergey Sharybin]

Commit: 6b28b7773057da6dc72067e4ff4f1d646e87aaca
Author: Sergey Sharybin
Date:   Fri Jan 24 15:14:28 2020 +0100
Branches: master
https://developer.blender.org/rB6b28b7773057da6dc72067e4ff4f1d646e87aaca

Depsgraph: Report FPS when running with --debug-depsgraph-time

The FPS here is measured based on a timestamp from when depsgraph
was previously evaluated.

Allows to ease investigating performance improvements/regressions
which are not related on animation system but on modifications on
a single frame (such as transforming vertex in edit mode).

===================================================================

M	source/blender/depsgraph/CMakeLists.txt
M	source/blender/depsgraph/intern/debug/deg_debug.cc
M	source/blender/depsgraph/intern/debug/deg_debug.h
A	source/blender/depsgraph/intern/debug/deg_time_average.h
M	source/blender/depsgraph/intern/eval/deg_eval.cc

===================================================================

diff --git a/source/blender/depsgraph/CMakeLists.txt b/source/blender/depsgraph/CMakeLists.txt
index f98b4caf08e..fad8bc22e08 100644
--- a/source/blender/depsgraph/CMakeLists.txt
+++ b/source/blender/depsgraph/CMakeLists.txt
@@ -106,6 +106,7 @@ set(SRC
   intern/builder/deg_builder_rna.h
   intern/builder/deg_builder_transitive.h
   intern/debug/deg_debug.h
+  intern/debug/deg_time_average.h
   intern/eval/deg_eval.h
   intern/eval/deg_eval_copy_on_write.h
   intern/eval/deg_eval_flush.h
diff --git a/source/blender/depsgraph/intern/debug/deg_debug.cc b/source/blender/depsgraph/intern/debug/deg_debug.cc
index b8db18c9958..00ff73b8f63 100644
--- a/source/blender/depsgraph/intern/debug/deg_debug.cc
+++ b/source/blender/depsgraph/intern/debug/deg_debug.cc
@@ -28,12 +28,48 @@
 #include "BLI_hash.h"
 #include "BLI_string.h"
 
+#include "PIL_time_utildefines.h"
+
 #include "BKE_global.h"
 
 namespace DEG {
 
-DepsgraphDebug::DepsgraphDebug() : flags(G.debug)
+DepsgraphDebug::DepsgraphDebug()
+    : flags(G.debug), is_ever_evaluated(false), graph_evaluation_start_time_(0)
+{
+}
+
+bool DepsgraphDebug::do_time_debug() const
+{
+  return ((G.debug & G_DEBUG_DEPSGRAPH_TIME) != 0);
+}
+
+void DepsgraphDebug::begin_graph_evaluation()
+{
+  if (!do_time_debug()) {
+    return;
+  }
+
+  const double current_time = PIL_check_seconds_timer();
+
+  if (is_ever_evaluated) {
+    fps_samples_.add_sample(current_time - graph_evaluation_start_time_);
+  }
+
+  graph_evaluation_start_time_ = current_time;
+}
+
+void DepsgraphDebug::end_graph_evaluation()
 {
+  if (!do_time_debug()) {
+    return;
+  }
+
+  const double graph_eval_end_time = PIL_check_seconds_timer();
+  printf("Depsgraph updated in %f seconds.\n", graph_eval_end_time - graph_evaluation_start_time_);
+  printf("Depsgraph evaluation FPS: %f\n", fps_samples_.get_averaged());
+
+  is_ever_evaluated = true;
 }
 
 bool terminal_do_color(void)
diff --git a/source/blender/depsgraph/intern/debug/deg_debug.h b/source/blender/depsgraph/intern/debug/deg_debug.h
index 90a2f7a25fd..21a802828dc 100644
--- a/source/blender/depsgraph/intern/debug/deg_debug.h
+++ b/source/blender/depsgraph/intern/debug/deg_debug.h
@@ -24,6 +24,7 @@
 #pragma once
 
 #include "intern/depsgraph_type.h"
+#include "intern/debug/deg_time_average.h"
 
 #include "BKE_global.h"
 
@@ -31,15 +32,36 @@
 
 namespace DEG {
 
-struct DepsgraphDebug {
+class DepsgraphDebug {
+ public:
   DepsgraphDebug();
 
+  bool do_time_debug() const;
+
+  void begin_graph_evaluation();
+  void end_graph_evaluation();
+
   /* NOTE: Corresponds to G_DEBUG_DEPSGRAPH_* flags. */
   int flags;
 
   /* Name of this dependency graph (is used for debug prints, helping to distinguish graphs
    * created for different view layer). */
   string name;
+
+  /* Is true when dependency graph was evaluated at least once.
+   * This is NOT an indication that depsgraph is at its evaluated state. */
+  bool is_ever_evaluated;
+
+ protected:
+  /* Maximum number of counters used to calculate frame rate of depsgraph update. */
+  static const constexpr int MAX_FPS_COUNTERS = 64;
+
+  /* Point in time when last graph evaluation began.
+   * Is initialized from begin_graph_evaluation() when time debug is enabled.
+   */
+  double graph_evaluation_start_time_;
+
+  AveragedTimeSampler<MAX_FPS_COUNTERS> fps_samples_;
 };
 
 #define DEG_DEBUG_PRINTF(depsgraph, type, ...) \
diff --git a/source/blender/depsgraph/intern/debug/deg_time_average.h b/source/blender/depsgraph/intern/debug/deg_time_average.h
new file mode 100644
index 00000000000..9794e9a88c3
--- /dev/null
+++ b/source/blender/depsgraph/intern/debug/deg_time_average.h
@@ -0,0 +1,71 @@
+/*
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU General Public License
+ * as published by the Free Software Foundation; either version 2
+ * of the License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+ *
+ * The Original Code is Copyright (C) 2013 Blender Foundation.
+ * All rights reserved.
+ */
+
+/** \file
+ * \ingroup depsgraph
+ */
+
+#pragma once
+
+namespace DEG {
+
+// Utility class which takes care of calculating average of time series, such as
+// FPS counters.
+template<int MaxSamples> class AveragedTimeSampler {
+ public:
+  AveragedTimeSampler() : num_samples_(0), next_sample_index_(0)
+  {
+  }
+
+  void add_sample(double value)
+  {
+    samples_[next_sample_index_] = value;
+
+    // Move to the next index, keeping wrapping at the end of array into account.
+    ++next_sample_index_;
+    if (next_sample_index_ == MaxSamples) {
+      next_sample_index_ = 0;
+    }
+
+    // Update number of stored samples.
+    if (num_samples_ != MaxSamples) {
+      ++num_samples_;
+    }
+  }
+
+  double get_averaged() const
+  {
+    double sum = 0.0;
+    for (int i = 0; i < num_samples_; ++i) {
+      sum += samples_[i];
+    }
+    return sum / num_samples_;
+  }
+
+ protected:
+  double samples_[MaxSamples];
+
+  // Number of samples which are actually stored in the array.
+  int num_samples_;
+
+  // Index in the samples_ array under which next sample will be stored.
+  int next_sample_index_;
+};
+
+}  // namespace DEG
diff --git a/source/blender/depsgraph/intern/eval/deg_eval.cc b/source/blender/depsgraph/intern/eval/deg_eval.cc
index bf0df085e36..9a10177a462 100644
--- a/source/blender/depsgraph/intern/eval/deg_eval.cc
+++ b/source/blender/depsgraph/intern/eval/deg_eval.cc
@@ -365,14 +365,15 @@ void deg_evaluate_on_refresh(Depsgraph *graph)
   if (BLI_gset_len(graph->entry_tags) == 0) {
     return;
   }
-  const bool do_time_debug = ((G.debug & G_DEBUG_DEPSGRAPH_TIME) != 0);
-  const double start_time = do_time_debug ? PIL_check_seconds_timer() : 0;
+
+  graph->debug.begin_graph_evaluation();
+
   graph->is_evaluating = true;
   depsgraph_ensure_view_layer(graph);
   /* Set up evaluation state. */
   DepsgraphEvalState state;
   state.graph = graph;
-  state.do_stats = do_time_debug;
+  state.do_stats = graph->debug.do_time_debug();
   state.need_single_thread_pass = false;
   /* Set up task scheduler and pull for threaded evaluation. */
   TaskScheduler *task_scheduler;
@@ -419,9 +420,8 @@ void deg_evaluate_on_refresh(Depsgraph *graph)
     BLI_task_scheduler_free(task_scheduler);
   }
   graph->is_evaluating = false;
-  if (do_time_debug) {
-    printf("Depsgraph updated in %f seconds.\n", PIL_check_seconds_timer() - start_time);
-  }
+
+  graph->debug.end_graph_evaluation();
 }
 
 }  // namespace DEG