Core/Metric: Log Map::Update() times (#25067)

* Core/Metric: Log Map::Update() times

* Add more performant version to reduce allocations when metrics are disabled

* Linux build fix

* Add metric stopwatch version that doesnt let users forget to _END it

* Fix linux build

* Code cleanup

* Add Map updates panel to General dashboard

* Add "Recent events" panel to General dashboard

* Apply latest codestyle changes

Co-authored-by: Shauren <shauren.trinity@gmail.com>

contrib/grafana/1_General.json

@@ -28,7 +28,7 @@
   "gnetId": null,
   "graphTooltip": 0,
   "id": 5,
-  "iteration": 1592337582972,
+  "iteration": 1595020261725,
   "links": [],
   "panels": [
     {
@@ -57,6 +57,12 @@
         "thresholdLabels": false,
         "thresholdMarkers": true
       },
+      "gridPos": {
+        "h": 3,
+        "w": 4,
+        "x": 0,
+        "y": 0
+      },
       "hideTimeOverride": false,
       "id": 5,
       "interval": null,
@@ -176,8 +182,8 @@
       },
       "gridPos": {
         "h": 3,
-        "w": 6,
-        "x": 6,
+        "w": 5,
+        "x": 4,
         "y": 0
       },
       "id": 6,
@@ -303,8 +309,8 @@
       },
       "gridPos": {
         "h": 3,
-        "w": 6,
-        "x": 12,
+        "w": 5,
+        "x": 9,
         "y": 0
       },
       "id": 7,
@@ -430,8 +436,8 @@
       },
       "gridPos": {
         "h": 3,
-        "w": 6,
-        "x": 18,
+        "w": 5,
+        "x": 14,
         "y": 0
       },
       "id": 8,
@@ -490,6 +496,8 @@
           "measurement": "update_time_diff",
           "orderByTime": "ASC",
           "policy": "default",
+          "query": "SELECT mean(\"value\") FROM \"update_time_diff\" WHERE (\"realm\" =~ /^$realm$/) AND $timeFilter GROUP BY time($__interval) fill(null)",
+          "rawQuery": true,
           "refId": "A",
           "resultFormat": "time_series",
           "select": [
@@ -530,6 +538,74 @@
       ],
       "valueName": "avg"
     },
+    {
+      "datasource": null,
+      "fieldConfig": {
+        "defaults": {
+          "custom": {}
+        },
+        "overrides": []
+      },
+      "gridPos": {
+        "h": 3,
+        "w": 5,
+        "x": 19,
+        "y": 0
+      },
+      "id": 12,
+      "options": {
+        "showLabels": false,
+        "showTime": true,
+        "sortOrder": "Descending",
+        "wrapLogMessage": true
+      },
+      "targets": [
+        {
+          "groupBy": [],
+          "measurement": "events",
+          "orderByTime": "ASC",
+          "policy": "default",
+          "query": "SELECT \"title\" FROM \"events\" WHERE (\"realm\" =~ /^$realm$/) order by \"time\" desc limit 2",
+          "rawQuery": true,
+          "refId": "A",
+          "resultFormat": "table",
+          "select": [
+            [
+              {
+                "params": [
+                  "title"
+                ],
+                "type": "field"
+              },
+              {
+                "params": [],
+                "type": "last"
+              }
+            ]
+          ],
+          "tags": []
+        }
+      ],
+      "timeFrom": null,
+      "timeShift": null,
+      "title": "Recent events",
+      "transformations": [
+        {
+          "id": "organize",
+          "options": {
+            "excludeByName": {
+              "title": false
+            },
+            "indexByName": {},
+            "renameByName": {
+              "Time": "",
+              "title": ""
+            }
+          }
+        }
+      ],
+      "type": "logs"
+    },
     {
       "aliasColors": {},
       "bars": false,
@@ -606,8 +682,10 @@
             }
           ],
           "measurement": "update_time_diff",
+          "orderByTime": "ASC",
           "policy": "default",
-          "query": "SELECT mean(\"value\") FROM \"update_time_diff\" WHERE \"realm\" =~ /$realm$/ AND $timeFilter GROUP BY time($interval) fill(null)",
+          "query": "SELECT max(\"value\") FROM \"update_time_diff\" WHERE (\"realm\" =~ /$realm$/) AND $timeFilter GROUP BY time($interval) fill(null)",
+          "rawQuery": false,
           "refId": "A",
           "resultFormat": "time_series",
           "select": [
@@ -620,7 +698,7 @@
               },
               {
                 "params": [],
-                "type": "mean"
+                "type": "max"
               }
             ]
           ],
@@ -659,6 +737,14 @@
         "short"
       ],
       "yaxes": [
+        {
+          "format": "ms",
+          "label": null,
+          "logBase": 1,
+          "max": null,
+          "min": null,
+          "show": true
+        },
         {
           "format": "short",
           "label": null,
@@ -666,6 +752,139 @@
           "max": null,
           "min": null,
           "show": true
+        }
+      ],
+      "yaxis": {
+        "align": false,
+        "alignLevel": null
+      }
+    },
+    {
+      "aliasColors": {},
+      "bars": false,
+      "dashLength": 10,
+      "dashes": false,
+      "datasource": null,
+      "fieldConfig": {
+        "defaults": {
+          "custom": {}
+        },
+        "overrides": []
+      },
+      "fill": 1,
+      "fillGradient": 0,
+      "gridPos": {
+        "h": 8,
+        "w": 24,
+        "x": 0,
+        "y": 10
+      },
+      "hiddenSeries": false,
+      "id": 10,
+      "legend": {
+        "avg": false,
+        "current": false,
+        "hideEmpty": false,
+        "hideZero": true,
+        "max": false,
+        "min": false,
+        "show": true,
+        "total": false,
+        "values": false
+      },
+      "lines": true,
+      "linewidth": 2,
+      "nullPointMode": "connected",
+      "options": {
+        "dataLinks": []
+      },
+      "percentage": false,
+      "pointradius": 2,
+      "points": false,
+      "renderer": "flot",
+      "seriesOverrides": [],
+      "spaceLength": 10,
+      "stack": false,
+      "steppedLine": false,
+      "targets": [
+        {
+          "alias": "Map $tag_map_id",
+          "groupBy": [
+            {
+              "params": [
+                "$__interval"
+              ],
+              "type": "time"
+            },
+            {
+              "params": [
+                "map_id"
+              ],
+              "type": "tag"
+            },
+            {
+              "params": [
+                "none"
+              ],
+              "type": "fill"
+            }
+          ],
+          "measurement": "map_update_time_diff",
+          "orderByTime": "ASC",
+          "policy": "default",
+          "query": "SELECT max(\"value\") FROM \"map_update_time_diff\" WHERE (\"realm\" =~ /^$realm$/) AND $timeFilter GROUP BY time($__interval), \"map_id\" fill(none)",
+          "rawQuery": false,
+          "refId": "A",
+          "resultFormat": "time_series",
+          "select": [
+            [
+              {
+                "params": [
+                  "value"
+                ],
+                "type": "field"
+              },
+              {
+                "params": [],
+                "type": "max"
+              }
+            ]
+          ],
+          "tags": [
+            {
+              "key": "realm",
+              "operator": "=~",
+              "value": "/^$realm$/"
+            }
+          ]
+        }
+      ],
+      "thresholds": [],
+      "timeFrom": null,
+      "timeRegions": [],
+      "timeShift": null,
+      "title": "Map update",
+      "tooltip": {
+        "shared": true,
+        "sort": 0,
+        "value_type": "individual"
+      },
+      "type": "graph",
+      "xaxis": {
+        "buckets": null,
+        "mode": "time",
+        "name": null,
+        "show": true,
+        "values": []
+      },
+      "yaxes": [
+        {
+          "format": "ms",
+          "label": null,
+          "logBase": 1,
+          "max": null,
+          "min": null,
+          "show": true
         },
         {
           "format": "short",
@@ -709,7 +928,7 @@
         "h": 7,
         "w": 24,
         "x": 0,
-        "y": 10
+        "y": 18
       },
       "hiddenSeries": false,
       "id": 4,
@@ -860,7 +1079,7 @@
         "h": 7,
         "w": 24,
         "x": 0,
-        "y": 17
+        "y": 25
       },
       "hiddenSeries": false,
       "id": 3,
@@ -1096,5 +1315,5 @@
   "timezone": "browser",
   "title": "General info",
   "uid": "BfuPZmZMz",
-  "version": 1
+  "version": 3
 }

src/common/Metric/Metric.cpp

@@ -279,6 +279,11 @@ std::string Metric::FormatInfluxDBTagValue(std::string const& value)
     return boost::replace_all_copy(value, " ", "\\ ");
 }
 
+std::string Metric::FormatInfluxDBValue(std::chrono::nanoseconds value)
+{
+    return FormatInfluxDBValue(std::chrono::duration_cast<std::chrono::milliseconds>(value).count());
+}
+
 Metric::Metric()
 {
 }

src/common/Metric/Metric.h

@@ -90,6 +90,7 @@ private:
     static std::string FormatInfluxDBValue(char const* value);
     static std::string FormatInfluxDBValue(double value);
     static std::string FormatInfluxDBValue(float value);
+    static std::string FormatInfluxDBValue(std::chrono::nanoseconds value);
 
     static std::string FormatInfluxDBTagValue(std::string const& value);
 
@@ -127,6 +128,34 @@ public:
 
 #define sMetric Metric::instance()
 
+
+template<typename LoggerType>
+class MetricStopWatch
+{
+public:
+    MetricStopWatch(LoggerType&& loggerFunc) :
+        _logger(std::forward<LoggerType>(loggerFunc)),
+        _startTime(sMetric->IsEnabled() ? std::chrono::steady_clock::now() : TimePoint())
+    {
+    }
+
+    ~MetricStopWatch()
+    {
+        if (sMetric->IsEnabled())
+            _logger(_startTime);
+    }
+
+private:
+    LoggerType _logger;
+    TimePoint _startTime;
+};
+
+template<typename LoggerType>
+MetricStopWatch<LoggerType> MakeMetricStopWatch(LoggerType&& loggerFunc)
+{
+    return { std::forward<LoggerType>(loggerFunc) };
+}
+
 #define TC_METRIC_TAG(name, value) { name, value }
 
 #ifdef PERFORMANCE_PROFILING
@@ -161,5 +190,10 @@ public:
         } while (0)                                                    \
         __pragma(warning(pop))
 #endif
+#define TC_METRIC_TIMER(category, ...)                           \
+        MetricStopWatch __tc_metric_stop_watch = MakeMetricStopWatch([&](TimePoint start) \
+        {                                                                                                             \
+            sMetric->LogValue(category, std::chrono::steady_clock::now() - start, { __VA_ARGS__ });               \
+        });
 
 #endif // METRIC_H__

src/server/game/Maps/MapUpdater.cpp

@@ -17,6 +17,7 @@
 
 #include "MapUpdater.h"
 #include "Map.h"
+#include "Metric.h"
 
 #include <mutex>
 
@@ -38,6 +39,7 @@ class MapUpdateRequest
 
         void call()
         {
+            TC_METRIC_TIMER("map_update_time_diff", TC_METRIC_TAG("map_id", std::to_string(m_map.GetId())));
             m_map.Update (m_diff);
             m_updater.update_finished();
         }