Calculate building lag and show it next to APM counter

src/citymania/cm_commands.cpp

@@ -9,6 +9,7 @@
 
 #include <queue>
 #include <vector>
+#include <chrono>
 
 
 namespace citymania {
@@ -19,7 +20,48 @@ std::map<size_t, std::pair<uint32, std::vector<CommandCallback>>> _command_callb
 std::queue<std::pair<size_t, uint32>> _command_sent;
 CommandCallback _current_callback = nullptr;
 bool _no_estimate_command = false;
-std::queue<std::pair<size_t, CommandCallback>> _callback_queue;
+
+template <typename T, int MaxLen>
+class SumLast {
+protected:
+    T sum {};
+    std::queue<T> values;
+public:
+    void reset() {
+        this->sum = {};
+        this->values = {};
+    }
+
+    void add(const T& value) {
+        if (this->values.size() == MaxLen) {
+            this->sum -= this->values.front();
+            this->values.pop();
+        }
+        this->sum += value;
+        this->values.push(value);
+    }
+
+    T get_sum() { return this->sum; }
+    size_t get_count() { return this->values.size(); }
+};
+
+struct CallbackQueueEntry {
+    size_t hash;
+    CommandCallback callback;
+    std::chrono::time_point<std::chrono::steady_clock> created;
+
+    CallbackQueueEntry(size_t hash, CommandCallback callback)
+            : hash{hash}, callback{callback} {
+        this->created = std::chrono::steady_clock::now();
+    }
+
+    double get_time_elapsed() {
+        return std::chrono::duration<double>(std::chrono::steady_clock::now() - this->created).count() * 1000;
+    }
+};
+
+SumLast<double, 100> _command_lag_tracker;
+std::queue<CallbackQueueEntry> _callback_queue;
 
 uint GetCurrentQueueDelay();
 
@@ -65,28 +107,30 @@ void BeforeNetworkCommandExecution(const CommandPacket* cp) {
     if (!cp->my_cmd) return;
     size_t hash = GetCommandHash(cp->cmd, cp->company, cp->err_msg, cp->callback, cp->tile, cp->data);
     Debug(misc, 5, "CM BeforeNetworkCommandExecution: cmd={} hash={}", cp->cmd, hash);
-    while (!_callback_queue.empty() && _callback_queue.front().first != hash) {
-        Debug(misc, 0, "CM Dismissing command from callback queue: hash={}", _callback_queue.front().first);
+    while (!_callback_queue.empty() && _callback_queue.front().hash != hash) {
+        Debug(misc, 0, "CM Dismissing command from callback queue: hash={}", _callback_queue.front().hash);
         _callback_queue.pop();
     }
     if (_callback_queue.empty()) {
         Debug(misc, 0, "CM Received unexpected network command: cmd={}", cp->cmd);
         return;
     }
-    _current_callback = _callback_queue.front().second;
+    auto &cbdata = _callback_queue.front();
+    _current_callback = cbdata.callback;
+    _command_lag_tracker.add(cbdata.get_time_elapsed());
     _callback_queue.pop();
     return;
 }
 
 void AfterNetworkCommandExecution(const CommandPacket* cp) {
-    Debug(misc, 0, "AfterNetworkCommandExecution {}", cp->cmd);
+    Debug(misc, 5, "AfterNetworkCommandExecution {}", cp->cmd);
     _current_callback = nullptr;
 }
 
 void AddCommandCallback(const CommandPacket *cp) {
     size_t hash = GetCommandHash(cp->cmd, cp->company, cp->err_msg, cp->callback, cp->tile, cp->data);
     Debug(misc, 5, "CM Added callback: cmd={} hash={}", cp->cmd, hash);
-    _callback_queue.push(std::make_pair(hash, _current_callback));
+    _callback_queue.emplace(hash, _current_callback);
     _current_callback = nullptr;
 }
 
@@ -134,6 +178,7 @@ void InitCommandQueue() {
     _commands_this_frame = 0;
     std::queue<CommandPacket>().swap(_outgoing_queue);  // clear queue
     _command_callbacks.clear();
+    _command_lag_tracker.reset();
 }
 
 bool CanSendCommand() {
@@ -168,4 +213,12 @@ void SendClientCommand(const CommandPacket *cp) {
     _outgoing_queue.push(*cp);
 }
 
+int get_average_command_lag() {
+    Debug(misc, 0, "Command lag {} / {}", _command_lag_tracker.get_sum(), _command_lag_tracker.get_count());
+    auto count = _command_lag_tracker.get_count();
+    if (count == 0) return 0;
+
+    return (int)(_command_lag_tracker.get_sum() / count);
+}
+
 }  // namespace citymania

src/citymania/cm_commands.hpp

@@ -19,6 +19,7 @@ void AfterNetworkCommandExecution(const CommandPacket* cp);
 void InitCommandQueue();
 void HandleNextClientFrame();
 void SendClientCommand(const CommandPacket *cp);
+int get_average_command_lag();
 
 }  // namespace citymania
 

src/citymania/cm_station_gui.cpp

@@ -33,7 +33,6 @@
 
 extern const Station *_viewport_highlight_station;
 extern TileHighlightData _thd;
-extern void MarkCatchmentTilesDirty();
 
 extern DiagDirection _road_station_picker_orientation;
 extern bool CheckClickOnViewportSign(const Viewport *vp, int x, int y, const ViewportSign *sign);
@@ -43,7 +42,6 @@ extern ViewportSignKdtree _viewport_sign_kdtree;
 extern AirportClassID _selected_airport_class;
 extern int _selected_airport_index;
 extern byte _selected_airport_layout;
-extern void CcBuildAirport(Commands cmd, const CommandCost &result, TileIndex tile);
 extern RailType _cur_railtype;  // rail_gui.cpp
 
 struct RailStationGUISettings {

src/command_func.h

@@ -17,6 +17,9 @@
 #include "core/backup_type.hpp"
 #include "misc/endian_buffer.hpp"
 #include "tile_map.h"
+#include "date_func.h"
+#include "core/random_func.hpp"  // CM for _random debug print
+
 
 struct CommandPacket;
 namespace citymania { void ExecuteCurrentCallback(const CommandCost &cost); }
@@ -420,6 +423,7 @@ protected:
 			return {};
 		}
 
+		Debug(misc, 0, "{}/{} {} {} company={} tile={}", _date, _date_fract, _random.state[0], GetCommandName(Tcmd), (int)_current_company, tile);
 		if (desync_log) LogCommandExecution(Tcmd, err_message, tile, EndianBufferWriter<CommandDataBuffer>::FromValue(args), false);
 
 		/* Actually try and execute the command. */

src/lang/english.txt

@@ -5980,7 +5980,7 @@ STR_CM_CONFIG_SETTING_SHADED_TREES_SERVER   :As server
 
 STR_CM_CONFIG_SETTING_SHOW_APM          :Show APM counter: {STRING2}
 STR_CM_CONFIG_SETTING_SHOW_APM_HELPTEXT :Adds APM (actions per minute) counter to the statusbar.
-STR_CM_STATUSBAR_APM                    :{WHITE}APM: {NUM} AVG: {NUM}
+STR_CM_STATUSBAR_APM                    :{WHITE}APM: {NUM} AVG: {NUM} LAG: {NUM}
 
 STR_CM_STATION_BUILD_SUPPLIES     :{BLACK}Supplies: {GOLD}
 

src/lang/german.txt

@@ -5977,7 +5977,7 @@ STR_CM_CONFIG_SETTING_SHADED_TREES_SERVER                       :Wie Server
 
 STR_CM_CONFIG_SETTING_SHOW_APM                                  :Zeige APM-Zähler: {STRING}
 STR_CM_CONFIG_SETTING_SHOW_APM_HELPTEXT                         :Fügt einen APM-Zähler (Aktionen pro Minute) zur Statusleiste hinzu.
-STR_CM_STATUSBAR_APM                                            :{WHITE}APM: {NUM} AVG: {NUM}
+STR_CM_STATUSBAR_APM                                            :{WHITE}APM: {NUM} AVG: {NUM} LAG: {NUM}
 STR_CM_STATION_BUILD_SUPPLIES                                   :{BLACK}Liefert: {GOLD}
 
 STR_CM_CONFIG_SETTING_GRAPH_BACKGROUND                          :Hintergrundfarbe von Graphen: {STRING}

src/network/network_command.cpp

@@ -545,6 +545,7 @@ void UnpackNetworkCommand(const CommandPacket* cp)
 {
 	citymania::BeforeNetworkCommandExecution(cp);
 	auto args = EndianBufferReader::ToValue<typename CommandTraits<Tcmd>::Args>(cp->data);
+	Debug(misc, 5, "UnpackNetworkCommand cmd={} my={} tile={}", GetCommandName(cp->cmd), cp->my_cmd, cp->tile);
 	Command<Tcmd>::PostFromNet(cp->err_msg, std::get<Tcb>(_callback_tuple), cp->my_cmd, cp->tile, args);
 	citymania::AfterNetworkCommandExecution(cp);
 }

src/statusbar_gui.cpp

@@ -33,6 +33,7 @@
 #include "table/sprites.h"
 
 #include "citymania/cm_hotkeys.hpp"
+#include "citymania/cm_commands.hpp"
 
 #include "safeguards.h"
 
@@ -137,6 +138,7 @@ struct StatusBarWindow : Window {
 				}
 				SetDParam(0, 999);
 				SetDParam(1, 999);
+				SetDParam(2, 9999);
 				d = GetStringBoundingBox(STR_CM_STATUSBAR_APM);
 				break;
 
@@ -212,6 +214,7 @@ struct StatusBarWindow : Window {
 					auto epm = citymania::GetEPM();
 					SetDParam(0, epm.second);
 					SetDParam(1, epm.first);
+					SetDParam(2, std::min(citymania::get_average_command_lag(), 9999));
 					DrawString(tr, STR_CM_STATUSBAR_APM, TC_FROMSTRING, SA_HOR_CENTER);
 				}
 				break;