Core/Metric: Log detailed metrics about each opcode handler (#25153)

* Core/Metric: Log detailed metrics about each opcode handler * Add new panel to Performance profiling dashboard and use fill(0) instead of fill(none) * Add new settings Metric.Threshold.* to be able to specify the minimum threshold for the specified metrics * Update dashboard * Change thresholds to be required to send the metrics. A TC_METRIC_DETAILED_TIMER metric with an expected threshold not configured will be ignored * Use typedef Milliseconds * Refresh realms on load
2026-01-15 23:20:36 +01:00 · 2020-07-28 12:27:54 +00:00
parent 8642aaaf92
commit 8a2c79c850
7 changed files with 198 additions and 14 deletions
--- a/contrib/grafana/2_Maps.json
+++ b/contrib/grafana/2_Maps.json
@@ -28,7 +28,7 @@
  "gnetId": null,
  "graphTooltip": 0,
  "id": 6,
-  "iteration": 1592337831334,
+  "iteration": 1595939001794,
  "links": [],
  "panels": [
    {
@@ -643,7 +643,7 @@
        "name": "realm",
        "options": [],
        "query": "show tag values from events with key = realm",
-        "refresh": true,
+        "refresh": 1,
        "regex": "",
        "skipUrlSync": false,
        "sort": 0,
@@ -687,5 +687,5 @@
  "timezone": "browser",
  "title": "Maps, vmaps and mmaps",
  "uid": "6IhqWiWGz",
-  "version": 1
+  "version": 2
 }
--- a/contrib/grafana/3_Network.json
+++ b/contrib/grafana/3_Network.json
@@ -28,7 +28,7 @@
  "gnetId": null,
  "graphTooltip": 0,
  "id": 7,
-  "iteration": 1592337929176,
+  "iteration": 1595939048589,
  "links": [],
  "panels": [
    {
@@ -232,7 +232,7 @@
        "name": "realm",
        "options": [],
        "query": "show tag values from events with key = realm",
-        "refresh": true,
+        "refresh": 1,
        "regex": "",
        "skipUrlSync": false,
        "sort": 0,
@@ -276,5 +276,5 @@
  "timezone": "browser",
  "title": "Network",
  "uid": "_QtkMmWMk",
-  "version": 1
+  "version": 2
 }
--- a/contrib/grafana/4_Performance_profiling.json
+++ b/contrib/grafana/4_Performance_profiling.json
@@ -29,7 +29,7 @@
  "gnetId": null,
  "graphTooltip": 0,
  "id": 15,
-  "iteration": 1595854392473,
+  "iteration": 1595882804610,
  "links": [],
  "panels": [
    {
@@ -246,7 +246,7 @@
            },
            {
              "params": [
-                "none"
+                "0"
              ],
              "type": "fill"
            }
@@ -297,7 +297,7 @@
            },
            {
              "params": [
-                "none"
+                "0"
              ],
              "type": "fill"
            }
@@ -440,7 +440,7 @@
            },
            {
              "params": [
-                "none"
+                "0"
              ],
              "type": "fill"
            }
@@ -1094,6 +1094,151 @@
        "align": false,
        "alignLevel": null
      }
+    },
+    {
+      "aliasColors": {},
+      "bars": true,
+      "dashLength": 10,
+      "dashes": false,
+      "datasource": null,
+      "fieldConfig": {
+        "defaults": {
+          "custom": {}
+        },
+        "overrides": []
+      },
+      "fill": 1,
+      "fillGradient": 0,
+      "gridPos": {
+        "h": 8,
+        "w": 12,
+        "x": 0,
+        "y": 31
+      },
+      "hiddenSeries": false,
+      "id": 11,
+      "legend": {
+        "alignAsTable": true,
+        "avg": false,
+        "current": false,
+        "hideEmpty": true,
+        "hideZero": true,
+        "max": true,
+        "min": false,
+        "rightSide": true,
+        "show": true,
+        "sort": "max",
+        "sortDesc": true,
+        "total": false,
+        "values": true
+      },
+      "lines": false,
+      "linewidth": 2,
+      "nullPointMode": "null",
+      "options": {
+        "dataLinks": []
+      },
+      "percentage": false,
+      "pointradius": 2,
+      "points": true,
+      "renderer": "flot",
+      "seriesOverrides": [],
+      "spaceLength": 10,
+      "stack": false,
+      "steppedLine": false,
+      "targets": [
+        {
+          "alias": "Opcode $tag_opcode",
+          "groupBy": [
+            {
+              "params": [
+                "$__interval"
+              ],
+              "type": "time"
+            },
+            {
+              "params": [
+                "opcode"
+              ],
+              "type": "tag"
+            },
+            {
+              "params": [
+                "null"
+              ],
+              "type": "fill"
+            }
+          ],
+          "measurement": "worldsession_update_opcode_time",
+          "orderByTime": "ASC",
+          "policy": "default",
+          "query": "SELECT max(\"value\") FROM \"worldsession_update_opcode_time\" WHERE (\"realm\" =~ /^$realm$/) AND $timeFilter GROUP BY time($__interval), \"opcode\" fill(null)",
+          "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": "Opcode handlers - Split",
+      "tooltip": {
+        "shared": false,
+        "sort": 2,
+        "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",
+          "label": null,
+          "logBase": 1,
+          "max": null,
+          "min": null,
+          "show": true
+        }
+      ],
+      "yaxis": {
+        "align": false,
+        "alignLevel": null
+      }
    }
  ],
  "refresh": "1m",
@@ -1150,5 +1295,5 @@
  "timezone": "",
  "title": "Performance profiling",
  "uid": "IRRL03nMk",
-  "version": 5
+  "version": 6
 }
--- a/src/common/Metric/Metric.cpp
+++ b/src/common/Metric/Metric.cpp
@@ -69,6 +69,15 @@ void Metric::LoadFromConfigs()
        _overallStatusTimerInterval = 1;
    }

+    _thresholds.clear();
+    std::vector<std::string> thresholdSettings = sConfigMgr->GetKeysByString("Metric.Threshold.");
+    for (std::string const& thresholdSetting : thresholdSettings)
+    {
+        int thresholdValue = sConfigMgr->GetIntDefault(thresholdSetting, 0);
+        std::string thresholdName = thresholdSetting.substr(strlen("Metric.Threshold."));
+        _thresholds[thresholdName] = thresholdValue;
+    }
+
    // Schedule a send at this point only if the config changed from Disabled to Enabled.
    // Cancel any scheduled operation if the config changed from Enabled to Disabled.
    if (_enabled && !previousValue)
@@ -106,6 +115,14 @@ void Metric::Update()
    }
 }

+bool Metric::ShouldLog(std::string const& category, int64 value) const
+{
+    auto threshold = _thresholds.find(category);
+    if (threshold == _thresholds.end())
+        return false;
+    return value >= threshold->second;
+}
+
 void Metric::LogEvent(std::string const& category, std::string const& title, std::string const& description)
 {
    using namespace std::chrono;
@@ -281,7 +298,7 @@ std::string Metric::FormatInfluxDBTagValue(std::string const& value)

 std::string Metric::FormatInfluxDBValue(std::chrono::nanoseconds value)
 {
-    return FormatInfluxDBValue(std::chrono::duration_cast<std::chrono::milliseconds>(value).count());
+    return FormatInfluxDBValue(std::chrono::duration_cast<Milliseconds>(value).count());
 }

 Metric::Metric()
--- a/src/common/Metric/Metric.h
+++ b/src/common/Metric/Metric.h
@@ -25,6 +25,7 @@
 #include <iosfwd>
 #include <memory>
 #include <string>
+#include <unordered_map>
 #include <vector>
 #include <utility>

@@ -77,6 +78,7 @@ private:
    std::string _databaseName;
    std::function<void()> _overallStatusLogger;
    std::string _realmName;
+    std::unordered_map<std::string, int64> _thresholds;

    bool Connect();
    void SendBatch();
@@ -104,6 +106,7 @@ public:
    void Initialize(std::string const& realmName, Trinity::Asio::IoContext& ioContext, std::function<void()> overallStatusLogger);
    void LoadFromConfigs();
    void Update();
+    bool ShouldLog(std::string const& category, int64 value) const;

    template<class T>
    void LogValue(std::string const& category, T value, std::vector<MetricTag> tags)
@@ -206,7 +209,9 @@ MetricStopWatch<LoggerType> MakeMetricStopWatch(LoggerType&& loggerFunc)
 #define TC_METRIC_DETAILED_TIMER(category, ...)                                                                  \
        MetricStopWatch TC_METRIC_UNIQUE_NAME(__tc_metric_stop_watch) = MakeMetricStopWatch([&](TimePoint start) \
        {                                                                                                        \
-            sMetric->LogValue(category, std::chrono::steady_clock::now() - start, { __VA_ARGS__ });              \
+            int64 duration = int64(std::chrono::duration_cast<Milliseconds>(std::chrono::steady_clock::now() - start).count()); \
+            if (sMetric->ShouldLog(category, duration))                                                          \
+                sMetric->LogValue(category, duration, { __VA_ARGS__ });                                          \
        });
 #  else
 #define TC_METRIC_DETAILED_TIMER(category, ...) ((void)0)
--- a/src/server/game/Server/WorldSession.cpp
+++ b/src/server/game/Server/WorldSession.cpp
@@ -291,7 +291,10 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)

    while (m_Socket && _recvQueue.next(packet, updater))
    {
-        ClientOpcodeHandler const* opHandle = opcodeTable[static_cast<OpcodeClient>(packet->GetOpcode())];
+        OpcodeClient opcode = static_cast<OpcodeClient>(packet->GetOpcode());
+        ClientOpcodeHandler const* opHandle = opcodeTable[opcode];
+        TC_METRIC_DETAILED_TIMER("worldsession_update_opcode_time", TC_METRIC_TAG("opcode", opHandle->Name));
+
        try
        {
            switch (opHandle->Status)
--- a/src/server/worldserver/worldserver.conf.dist
+++ b/src/server/worldserver/worldserver.conf.dist
@@ -4066,5 +4066,19 @@ Metric.ConnectionInfo = "127.0.0.1;8086;worldserver"

 Metric.OverallStatusInterval = 1

+#
+#  Metric threshold values: Given a metric "name"
+#    Metric.Threshold.name
+#        Description: Skips sending statistics with a value lower than the config value.
+#                     If the threshold is commented out, the metric will be ignored.
+#                     Only metrics logged with TC_METRIC_DETAILED_TIMER in the sources are affected.
+#                     Disabled by default. Requires WITH_DETAILED_METRICS CMake flag.
+#
+#        Format:      Value as integer
+#
+
+#Metric.Threshold.world_update_sessions_time = 100
+#Metric.Threshold.worldsession_update_opcode_time = 50
+
 #
 ###################################################################################################