From f5a8593b11382b70ee969dc93b71f34fb0cad5df Mon Sep 17 00:00:00 2001 From: sfan5 Date: Mon, 9 May 2022 21:20:58 +0200 Subject: [PATCH] Add more Prometheus metrics (#12274) --- src/emerge.cpp | 25 +++++++++- src/emerge.h | 16 ++++++- src/map.cpp | 28 +++++++++-- src/map.h | 10 ++++ src/server.cpp | 40 +++++++++++----- src/server.h | 4 +- src/serverenvironment.cpp | 25 +++++++++- src/serverenvironment.h | 18 +++++-- src/util/metricsbackend.cpp | 95 +++++++++++++++++++++++++++++++------ src/util/metricsbackend.h | 84 ++++---------------------------- 10 files changed, 225 insertions(+), 120 deletions(-) diff --git a/src/emerge.cpp b/src/emerge.cpp index 3760b24e6..5c1569f04 100644 --- a/src/emerge.cpp +++ b/src/emerge.cpp @@ -61,7 +61,9 @@ public: void cancelPendingItems(); - static void runCompletionCallbacks( +protected: + + void runCompletionCallbacks( const v3s16 &pos, EmergeAction action, const EmergeCallbackList &callbacks); @@ -138,7 +140,7 @@ EmergeParams::EmergeParams(EmergeManager *parent, const BiomeGen *biomegen, //// EmergeManager //// -EmergeManager::EmergeManager(Server *server) +EmergeManager::EmergeManager(Server *server, MetricsBackend *mb) { this->ndef = server->getNodeDefManager(); this->biomemgr = new BiomeManager(server); @@ -156,6 +158,17 @@ EmergeManager::EmergeManager(Server *server) enable_mapgen_debug_info = g_settings->getBool("enable_mapgen_debug_info"); + STATIC_ASSERT(ARRLEN(emergeActionStrs) == ARRLEN(m_completed_emerge_counter), + enum_size_mismatches); + for (u32 i = 0; i < ARRLEN(m_completed_emerge_counter); i++) { + std::string help_str("Number of completed emerges with status "); + help_str.append(emergeActionStrs[i]); + m_completed_emerge_counter[i] = mb->addCounter( + "minetest_emerge_completed", help_str, + {{"status", emergeActionStrs[i]}} + ); + } + s16 nthreads = 1; g_settings->getS16NoEx("num_emerge_threads", nthreads); // If automatic, leave a proc for the main thread and one for @@ -489,6 +502,12 @@ EmergeThread *EmergeManager::getOptimalThread() return m_threads[index]; } +void EmergeManager::reportCompletedEmerge(EmergeAction action) +{ + assert((int)action < ARRLEN(m_completed_emerge_counter)); + m_completed_emerge_counter[(int)action]->increment(); +} + //// //// EmergeThread @@ -540,6 +559,8 @@ void EmergeThread::cancelPendingItems() void EmergeThread::runCompletionCallbacks(const v3s16 &pos, EmergeAction action, const EmergeCallbackList &callbacks) { + m_emerge->reportCompletedEmerge(action); + for (size_t i = 0; i != callbacks.size(); i++) { EmergeCompletionCallback callback; void *param; diff --git a/src/emerge.h b/src/emerge.h index 61e7bda63..1bac4b708 100644 --- a/src/emerge.h +++ b/src/emerge.h @@ -24,6 +24,7 @@ with this program; if not, write to the Free Software Foundation, Inc., #include "network/networkprotocol.h" #include "irr_v3d.h" #include "util/container.h" +#include "util/metricsbackend.h" #include "mapgen/mapgen.h" // for MapgenParams #include "map.h" @@ -69,6 +70,14 @@ enum EmergeAction { EMERGE_GENERATED, }; +const static std::string emergeActionStrs[] = { + "cancelled", + "errored", + "from_memory", + "from_disk", + "generated", +}; + // Callback typedef void (*EmergeCompletionCallback)( v3s16 blockpos, EmergeAction action, void *param); @@ -138,7 +147,7 @@ public: MapSettingsManager *map_settings_mgr; // Methods - EmergeManager(Server *server); + EmergeManager(Server *server, MetricsBackend *mb); ~EmergeManager(); DISABLE_CLASS_COPY(EmergeManager); @@ -197,6 +206,9 @@ private: u32 m_qlimit_diskonly; u32 m_qlimit_generate; + // Emerge metrics + MetricCounterPtr m_completed_emerge_counter[5]; + // Managers of various map generation-related components // Note that each Mapgen gets a copy(!) of these to work with BiomeGen *biomegen; @@ -218,5 +230,7 @@ private: bool popBlockEmergeData(v3s16 pos, BlockEmergeData *bedata); + void reportCompletedEmerge(EmergeAction action); + friend class EmergeThread; }; diff --git a/src/map.cpp b/src/map.cpp index 5153dcaa9..ce69accb5 100644 --- a/src/map.cpp +++ b/src/map.cpp @@ -336,6 +336,7 @@ void Map::timerUpdate(float dtime, float unload_timeout, u32 max_loaded_blocks, u32 saved_blocks_count = 0; u32 block_count_all = 0; + const auto start_time = porting::getTimeUs(); beginSave(); // If there is no practical limit, we spare creation of mapblock_queue @@ -377,6 +378,7 @@ void Map::timerUpdate(float dtime, float unload_timeout, u32 max_loaded_blocks, } } + // Delete sector if we emptied it if (all_blocks_deleted) { sector_deletion_queue.push_back(sector_it.first); } @@ -395,6 +397,7 @@ void Map::timerUpdate(float dtime, float unload_timeout, u32 max_loaded_blocks, } } block_count_all = mapblock_queue.size(); + // Delete old blocks, and blocks over the limit from the memory while (!mapblock_queue.empty() && (mapblock_queue.size() > max_loaded_blocks || mapblock_queue.top().block->getUsageTimer() > unload_timeout)) { @@ -425,6 +428,7 @@ void Map::timerUpdate(float dtime, float unload_timeout, u32 max_loaded_blocks, deleted_blocks_count++; block_count_all--; } + // Delete empty sectors for (auto §or_it : m_sectors) { if (sector_it.second->empty()) { @@ -432,7 +436,11 @@ void Map::timerUpdate(float dtime, float unload_timeout, u32 max_loaded_blocks, } } } + endSave(); + const auto end_time = porting::getTimeUs(); + + reportMetrics(end_time - start_time, saved_blocks_count, block_count_all); // Finally delete the empty sectors deleteSectors(sector_deletion_queue); @@ -1218,7 +1226,12 @@ ServerMap::ServerMap(const std::string &savedir, IGameDef *gamedef, m_savedir = savedir; m_map_saving_enabled = false; - m_save_time_counter = mb->addCounter("minetest_core_map_save_time", "Map save time (in nanoseconds)"); + m_save_time_counter = mb->addCounter( + "minetest_map_save_time", "Time spent saving blocks (in microseconds)"); + m_save_count_counter = mb->addCounter( + "minetest_map_saved_blocks", "Number of blocks saved"); + m_loaded_blocks_gauge = mb->addGauge( + "minetest_map_loaded_blocks", "Number of loaded blocks"); m_map_compression_level = rangelim(g_settings->getS16("map_compression_level_disk"), -1, 9); @@ -1594,6 +1607,13 @@ void ServerMap::updateVManip(v3s16 pos) vm->m_is_dirty = true; } +void ServerMap::reportMetrics(u64 save_time_us, u32 saved_blocks, u32 all_blocks) +{ + m_loaded_blocks_gauge->set(all_blocks); + m_save_time_counter->increment(save_time_us); + m_save_count_counter->increment(saved_blocks); +} + void ServerMap::save(ModifiedState save_level) { if (!m_map_saving_enabled) { @@ -1601,7 +1621,7 @@ void ServerMap::save(ModifiedState save_level) return; } - u64 start_time = porting::getTimeNs(); + const auto start_time = porting::getTimeUs(); if(save_level == MOD_STATE_CLEAN) infostream<<"ServerMap: Saving whole map, this can take time." @@ -1662,8 +1682,8 @@ void ServerMap::save(ModifiedState save_level) modprofiler.print(infostream); } - auto end_time = porting::getTimeNs(); - m_save_time_counter->increment(end_time - start_time); + const auto end_time = porting::getTimeUs(); + reportMetrics(end_time - start_time, block_count, block_count_all); } void ServerMap::listAllLoadableBlocks(std::vector &dst) diff --git a/src/map.h b/src/map.h index 21e3dbd6c..1e5499586 100644 --- a/src/map.h +++ b/src/map.h @@ -275,6 +275,9 @@ protected: // This stores the properties of the nodes on the map. const NodeDefManager *m_nodedef; + // Can be implemented by child class + virtual void reportMetrics(u64 save_time_us, u32 saved_blocks, u32 all_blocks) {} + bool determineAdditionalOcclusionCheck(const v3s16 &pos_camera, const core::aabbox3d &block_bounds, v3s16 &check); bool isOccluded(const v3s16 &pos_camera, const v3s16 &pos_target, @@ -392,6 +395,10 @@ public: MapSettingsManager settings_mgr; +protected: + + void reportMetrics(u64 save_time_us, u32 saved_blocks, u32 all_blocks) override; + private: friend class LuaVoxelManip; @@ -420,7 +427,10 @@ private: MapDatabase *dbase = nullptr; MapDatabase *dbase_ro = nullptr; + // Map metrics + MetricGaugePtr m_loaded_blocks_gauge; MetricCounterPtr m_save_time_counter; + MetricCounterPtr m_save_count_counter; }; diff --git a/src/server.cpp b/src/server.cpp index d85a2e95a..ebe1d1f6b 100644 --- a/src/server.cpp +++ b/src/server.cpp @@ -269,9 +269,15 @@ Server::Server( "minetest_core_latency", "Latency value (in seconds)"); - m_aom_buffer_counter = m_metrics_backend->addCounter( - "minetest_core_aom_generated_count", - "Number of active object messages generated"); + + const std::string aom_types[] = {"reliable", "unreliable"}; + for (u32 i = 0; i < ARRLEN(aom_types); i++) { + std::string help_str("Number of active object messages generated ("); + help_str.append(aom_types[i]).append(")"); + m_aom_buffer_counter[i] = m_metrics_backend->addCounter( + "minetest_core_aom_generated_count", help_str, + {{"type", aom_types[i]}}); + } m_packet_recv_counter = m_metrics_backend->addCounter( "minetest_core_server_packet_recv", @@ -281,6 +287,10 @@ Server::Server( "minetest_core_server_packet_recv_processed", "Valid received packets processed"); + m_map_edit_event_counter = m_metrics_backend->addCounter( + "minetest_core_map_edit_events", + "Number of map edit events"); + m_lag_gauge->set(g_settings->getFloat("dedicated_server_step")); } @@ -397,7 +407,7 @@ void Server::init() } // Create emerge manager - m_emerge = new EmergeManager(this); + m_emerge = new EmergeManager(this, m_metrics_backend.get()); // Create ban manager std::string ban_path = m_path_world + DIR_DELIM "ipban.txt"; @@ -462,7 +472,8 @@ void Server::init() // Initialize Environment m_startup_server_map = nullptr; // Ownership moved to ServerEnvironment - m_env = new ServerEnvironment(servermap, m_script, this, m_path_world); + m_env = new ServerEnvironment(servermap, m_script, this, + m_path_world, m_metrics_backend.get()); m_inventory_mgr->setEnv(m_env); m_clients.setEnv(m_env); @@ -623,6 +634,7 @@ void Server::AsyncRunStep(bool initial_step) max_lag = dtime; } m_env->reportMaxLagEstimate(max_lag); + // Step environment m_env->step(dtime); } @@ -773,10 +785,14 @@ void Server::AsyncRunStep(bool initial_step) // Get active object messages from environment ActiveObjectMessage aom(0); - u32 aom_count = 0; + u32 count_reliable = 0, count_unreliable = 0; for(;;) { if (!m_env->getActiveObjectMessage(&aom)) break; + if (aom.reliable) + count_reliable++; + else + count_unreliable++; std::vector* message_list = nullptr; auto n = buffered_messages.find(aom.id); @@ -787,10 +803,10 @@ void Server::AsyncRunStep(bool initial_step) message_list = n->second; } message_list->push_back(std::move(aom)); - aom_count++; } - m_aom_buffer_counter->increment(aom_count); + m_aom_buffer_counter[0]->increment(count_reliable); + m_aom_buffer_counter[1]->increment(count_unreliable); { ClientInterface::AutoLock clientlock(m_clients); @@ -864,15 +880,13 @@ void Server::AsyncRunStep(bool initial_step) // We will be accessing the environment MutexAutoLock lock(m_env_mutex); - // Don't send too many at a time - //u32 count = 0; - - // Single change sending is disabled if queue size is not small + // Single change sending is disabled if queue size is big bool disable_single_change_sending = false; if(m_unsent_map_edit_queue.size() >= 4) disable_single_change_sending = true; - int event_count = m_unsent_map_edit_queue.size(); + const auto event_count = m_unsent_map_edit_queue.size(); + m_map_edit_event_counter->increment(event_count); // We'll log the amount of each Profiler prof; diff --git a/src/server.h b/src/server.h index b1b9675d9..ecba30b95 100644 --- a/src/server.h +++ b/src/server.h @@ -724,11 +724,11 @@ private: MetricCounterPtr m_uptime_counter; MetricGaugePtr m_player_gauge; MetricGaugePtr m_timeofday_gauge; - // current server step lag MetricGaugePtr m_lag_gauge; - MetricCounterPtr m_aom_buffer_counter; + MetricCounterPtr m_aom_buffer_counter[2]; // [0] = rel, [1] = unrel MetricCounterPtr m_packet_recv_counter; MetricCounterPtr m_packet_recv_processed_counter; + MetricCounterPtr m_map_edit_event_counter; }; /* diff --git a/src/serverenvironment.cpp b/src/serverenvironment.cpp index 493210744..630c111c5 100644 --- a/src/serverenvironment.cpp +++ b/src/serverenvironment.cpp @@ -393,7 +393,7 @@ static std::random_device seed; ServerEnvironment::ServerEnvironment(ServerMap *map, ServerScripting *scriptIface, Server *server, - const std::string &path_world): + const std::string &path_world, MetricsBackend *mb): Environment(server), m_map(map), m_script(scriptIface), @@ -460,6 +460,15 @@ ServerEnvironment::ServerEnvironment(ServerMap *map, m_player_database = openPlayerDatabase(player_backend_name, path_world, conf); m_auth_database = openAuthDatabase(auth_backend_name, path_world, conf); + + m_step_time_counter = mb->addCounter( + "minetest_env_step_time", "Time spent in environment step (in microseconds)"); + + m_active_block_gauge = mb->addGauge( + "minetest_env_active_blocks", "Number of active blocks"); + + m_active_object_gauge = mb->addGauge( + "minetest_env_active_objects", "Number of active objects"); } ServerEnvironment::~ServerEnvironment() @@ -1283,6 +1292,8 @@ void ServerEnvironment::clearObjects(ClearObjectsMode mode) void ServerEnvironment::step(float dtime) { ScopeProfiler sp2(g_profiler, "ServerEnv::step()", SPT_AVG); + const auto start_time = porting::getTimeUs(); + /* Step time of day */ stepTimeOfDay(dtime); @@ -1352,6 +1363,8 @@ void ServerEnvironment::step(float dtime) m_active_blocks.update(players, active_block_range, active_object_range, blocks_removed, blocks_added); + m_active_block_gauge->set(m_active_blocks.size()); + /* Handle removed blocks */ @@ -1497,9 +1510,12 @@ void ServerEnvironment::step(float dtime) send_recommended = true; } - auto cb_state = [this, dtime, send_recommended] (ServerActiveObject *obj) { + u32 object_count = 0; + + auto cb_state = [&] (ServerActiveObject *obj) { if (obj->isGone()) return; + object_count++; // Step object obj->step(dtime, send_recommended); @@ -1507,6 +1523,8 @@ void ServerEnvironment::step(float dtime) obj->dumpAOMessagesToQueue(m_active_object_messages); }; m_ao_manager.step(dtime, cb_state); + + m_active_object_gauge->set(object_count); } /* @@ -1548,6 +1566,9 @@ void ServerEnvironment::step(float dtime) // Send outdated detached inventories m_server->sendDetachedInventories(PEER_ID_INEXISTENT, true); + + const auto end_time = porting::getTimeUs(); + m_step_time_counter->increment(end_time - start_time); } ServerEnvironment::BlockStatus ServerEnvironment::getBlockStatus(v3s16 blockpos) diff --git a/src/serverenvironment.h b/src/serverenvironment.h index 8733c2dd2..5dc329a60 100644 --- a/src/serverenvironment.h +++ b/src/serverenvironment.h @@ -25,6 +25,7 @@ with this program; if not, write to the Free Software Foundation, Inc., #include "settings.h" #include "server/activeobjectmgr.h" #include "util/numeric.h" +#include "util/metricsbackend.h" #include #include @@ -167,19 +168,21 @@ public: std::set &blocks_removed, std::set &blocks_added); - bool contains(v3s16 p){ + bool contains(v3s16 p) const { return (m_list.find(p) != m_list.end()); } - void clear(){ + auto size() const { + return m_list.size(); + } + + void clear() { m_list.clear(); } std::set m_list; std::set m_abm_list; std::set m_forceloaded_list; - -private: }; /* @@ -198,7 +201,7 @@ class ServerEnvironment : public Environment { public: ServerEnvironment(ServerMap *map, ServerScripting *scriptIface, - Server *server, const std::string &path_world); + Server *server, const std::string &path_world, MetricsBackend *mb); ~ServerEnvironment(); Map & getMap(); @@ -487,5 +490,10 @@ private: std::unordered_map m_particle_spawners; std::unordered_map m_particle_spawner_attachments; + // Environment metrics + MetricCounterPtr m_step_time_counter; + MetricGaugePtr m_active_block_gauge; + MetricGaugePtr m_active_object_gauge; + ServerActiveObject* createSAO(ActiveObjectType type, v3f pos, const std::string &data); }; diff --git a/src/util/metricsbackend.cpp b/src/util/metricsbackend.cpp index c3b7def62..63b49ac0a 100644 --- a/src/util/metricsbackend.cpp +++ b/src/util/metricsbackend.cpp @@ -18,6 +18,7 @@ with this program; if not, write to the Free Software Foundation, Inc., */ #include "metricsbackend.h" +#include "util/thread.h" #if USE_PROMETHEUS #include #include @@ -27,18 +28,78 @@ with this program; if not, write to the Free Software Foundation, Inc., #include "settings.h" #endif -MetricCounterPtr MetricsBackend::addCounter( - const std::string &name, const std::string &help_str) +/* Plain implementation */ + +class SimpleMetricCounter : public MetricCounter { - return std::make_shared(name, help_str); +public: + SimpleMetricCounter() : MetricCounter(), m_counter(0.0) {} + + virtual ~SimpleMetricCounter() {} + + void increment(double number) override + { + MutexAutoLock lock(m_mutex); + m_counter += number; + } + double get() const override + { + MutexAutoLock lock(m_mutex); + return m_counter; + } + +private: + mutable std::mutex m_mutex; + double m_counter; +}; + +class SimpleMetricGauge : public MetricGauge +{ +public: + SimpleMetricGauge() : MetricGauge(), m_gauge(0.0) {} + + virtual ~SimpleMetricGauge() {} + + void increment(double number) override + { + MutexAutoLock lock(m_mutex); + m_gauge += number; + } + void decrement(double number) override + { + MutexAutoLock lock(m_mutex); + m_gauge -= number; + } + void set(double number) override + { + MutexAutoLock lock(m_mutex); + m_gauge = number; + } + double get() const override + { + MutexAutoLock lock(m_mutex); + return m_gauge; + } + +private: + mutable std::mutex m_mutex; + double m_gauge; +}; + +MetricCounterPtr MetricsBackend::addCounter( + const std::string &name, const std::string &help_str, Labels labels) +{ + return std::make_shared(); } MetricGaugePtr MetricsBackend::addGauge( - const std::string &name, const std::string &help_str) + const std::string &name, const std::string &help_str, Labels labels) { - return std::make_shared(name, help_str); + return std::make_shared(); } +/* Prometheus backend */ + #if USE_PROMETHEUS class PrometheusMetricCounter : public MetricCounter @@ -47,13 +108,14 @@ public: PrometheusMetricCounter() = delete; PrometheusMetricCounter(const std::string &name, const std::string &help_str, + MetricsBackend::Labels labels, std::shared_ptr registry) : MetricCounter(), m_family(prometheus::BuildCounter() .Name(name) .Help(help_str) .Register(*registry)), - m_counter(m_family.Add({})) + m_counter(m_family.Add(labels)) { } @@ -73,13 +135,14 @@ public: PrometheusMetricGauge() = delete; PrometheusMetricGauge(const std::string &name, const std::string &help_str, + MetricsBackend::Labels labels, std::shared_ptr registry) : MetricGauge(), m_family(prometheus::BuildGauge() .Name(name) .Help(help_str) .Register(*registry)), - m_gauge(m_family.Add({})) + m_gauge(m_family.Add(labels)) { } @@ -107,10 +170,12 @@ public: virtual ~PrometheusMetricsBackend() {} - virtual MetricCounterPtr addCounter( - const std::string &name, const std::string &help_str); - virtual MetricGaugePtr addGauge( - const std::string &name, const std::string &help_str); + MetricCounterPtr addCounter( + const std::string &name, const std::string &help_str, + Labels labels = {}) override; + MetricGaugePtr addGauge( + const std::string &name, const std::string &help_str, + Labels labels = {}) override; private: std::unique_ptr m_exposer; @@ -118,15 +183,15 @@ private: }; MetricCounterPtr PrometheusMetricsBackend::addCounter( - const std::string &name, const std::string &help_str) + const std::string &name, const std::string &help_str, Labels labels) { - return std::make_shared(name, help_str, m_registry); + return std::make_shared(name, help_str, labels, m_registry); } MetricGaugePtr PrometheusMetricsBackend::addGauge( - const std::string &name, const std::string &help_str) + const std::string &name, const std::string &help_str, Labels labels) { - return std::make_shared(name, help_str, m_registry); + return std::make_shared(name, help_str, labels, m_registry); } MetricsBackend *createPrometheusMetricsBackend() diff --git a/src/util/metricsbackend.h b/src/util/metricsbackend.h index c37306392..644c73325 100644 --- a/src/util/metricsbackend.h +++ b/src/util/metricsbackend.h @@ -19,8 +19,9 @@ with this program; if not, write to the Free Software Foundation, Inc., #pragma once #include +#include +#include #include "config.h" -#include "util/thread.h" class MetricCounter { @@ -35,38 +36,6 @@ public: typedef std::shared_ptr MetricCounterPtr; -class SimpleMetricCounter : public MetricCounter -{ -public: - SimpleMetricCounter() = delete; - - virtual ~SimpleMetricCounter() {} - - SimpleMetricCounter(const std::string &name, const std::string &help_str) : - MetricCounter(), m_name(name), m_help_str(help_str), - m_counter(0.0) - { - } - - virtual void increment(double number) - { - MutexAutoLock lock(m_mutex); - m_counter += number; - } - virtual double get() const - { - MutexAutoLock lock(m_mutex); - return m_counter; - } - -private: - std::string m_name; - std::string m_help_str; - - mutable std::mutex m_mutex; - double m_counter; -}; - class MetricGauge { public: @@ -81,47 +50,6 @@ public: typedef std::shared_ptr MetricGaugePtr; -class SimpleMetricGauge : public MetricGauge -{ -public: - SimpleMetricGauge() = delete; - - SimpleMetricGauge(const std::string &name, const std::string &help_str) : - MetricGauge(), m_name(name), m_help_str(help_str), m_gauge(0.0) - { - } - - virtual ~SimpleMetricGauge() {} - - virtual void increment(double number) - { - MutexAutoLock lock(m_mutex); - m_gauge += number; - } - virtual void decrement(double number) - { - MutexAutoLock lock(m_mutex); - m_gauge -= number; - } - virtual void set(double number) - { - MutexAutoLock lock(m_mutex); - m_gauge = number; - } - virtual double get() const - { - MutexAutoLock lock(m_mutex); - return m_gauge; - } - -private: - std::string m_name; - std::string m_help_str; - - mutable std::mutex m_mutex; - double m_gauge; -}; - class MetricsBackend { public: @@ -129,10 +57,14 @@ public: virtual ~MetricsBackend() {} + typedef std::initializer_list> Labels; + virtual MetricCounterPtr addCounter( - const std::string &name, const std::string &help_str); + const std::string &name, const std::string &help_str, + Labels labels = {}); virtual MetricGaugePtr addGauge( - const std::string &name, const std::string &help_str); + const std::string &name, const std::string &help_str, + Labels labels = {}); }; #if USE_PROMETHEUS