From 26ae2e29ebd047dbae382f68194c3b646a2a1288 Mon Sep 17 00:00:00 2001 From: Sven Czarnian Date: Sun, 23 Apr 2023 19:17:14 +0200 Subject: [PATCH 1/7] introduce a performance measurement framework --- CMakeLists.txt | 1 + logging/Performance.h | 67 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 68 insertions(+) create mode 100644 logging/Performance.h diff --git a/CMakeLists.txt b/CMakeLists.txt index ad9b663..84ef10d 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -62,6 +62,7 @@ SET(SOURCE_FILES com/Server.h logging/Logger.cpp logging/Logger.h + logging/Performance.h logging/sqlite3.c logging/sqlite3.h logging/sqlite3ext.h diff --git a/logging/Performance.h b/logging/Performance.h new file mode 100644 index 0000000..39b6745 --- /dev/null +++ b/logging/Performance.h @@ -0,0 +1,67 @@ +#pragma once + +#include +#include +#include +#include + +#include "Logger.h" + +#define PERFORMANCE_MEASUREMENT 1 + +namespace vacdm { +namespace logging { + class Performance { + private: + std::string m_name; + std::uint64_t m_average; + std::int64_t m_minimum; + std::int64_t m_maximum; + std::uint32_t m_cycleCount; + std::chrono::high_resolution_clock::time_point m_startTime; + std::chrono::high_resolution_clock::time_point m_lastLogStamp; + + public: + Performance(const std::string& name) : + m_name(name), + m_average(0), + m_minimum(std::numeric_limits::max()), + m_maximum(std::numeric_limits::min()), + m_cycleCount(0), + m_startTime(), + m_lastLogStamp(std::chrono::high_resolution_clock::now()) {} + + void start() { +#if PERFORMANCE_MEASUREMENT + this->m_startTime = std::chrono::high_resolution_clock::now(); +#endif + } + + void stop() { +#if PERFORMANCE_MEASUREMENT + const auto now = std::chrono::high_resolution_clock::now(); + const auto delta = std::chrono::duration_cast(now - this->m_startTime).count(); + + this->m_minimum = std::min(this->m_minimum, delta); + this->m_maximum = std::max(this->m_maximum, delta); + if (this->m_cycleCount == 0) + this->m_average = delta; + else + this->m_average = static_cast((this->m_average + delta) * 0.5); + + if (std::chrono::duration_cast(now - this->m_lastLogStamp).count() >= 1) { + std::stringstream stream; + stream << "Performance statistics:" << std::endl; + stream << " Average: " << std::to_string(this->m_average) << " us" << std::endl; + stream << " Minimum: " << std::to_string(this->m_minimum) << " us" << std::endl; + stream << " Maximum: " << std::to_string(this->m_maximum) << " us" << std::endl; + + Logger::instance().log("Performance-" + this->m_name, Logger::Level::Info, stream.str()); + + this->m_lastLogStamp = now; + } +#endif + } + }; +} +} From dd838f0be33e1011796f5de58ff6b3fdd41b5dca Mon Sep 17 00:00:00 2001 From: Sven Czarnian Date: Sun, 23 Apr 2023 19:17:52 +0200 Subject: [PATCH 2/7] introduce a mutex-performance class to measure the time in critical sections and how long it takes to acquire locks --- CMakeLists.txt | 1 + com/PerformanceLock.h | 35 +++++++++++++++++++++++++++++++++++ 2 files changed, 36 insertions(+) create mode 100644 com/PerformanceLock.h diff --git a/CMakeLists.txt b/CMakeLists.txt index 84ef10d..96d9ffc 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -58,6 +58,7 @@ SET(SOURCE_FILES config/FileFormat.h com/Airport.cpp com/Airport.h + com/PerformanceLock.h com/Server.cpp com/Server.h logging/Logger.cpp diff --git a/com/PerformanceLock.h b/com/PerformanceLock.h new file mode 100644 index 0000000..28bb84c --- /dev/null +++ b/com/PerformanceLock.h @@ -0,0 +1,35 @@ +#pragma once + +#include + +#include + +namespace vacdm { +namespace com { + class PerformanceLock { + private: + vacdm::logging::Performance m_acquireTime; + vacdm::logging::Performance m_criticalSectionTime; + + std::mutex m_lock; + public: + PerformanceLock(const std::string& component) : + m_acquireTime("LockAcquire" + component), + m_criticalSectionTime("CriticalSectionAcquire" + component), + m_lock() {} + + void lock() { + this->m_acquireTime.start(); + this->m_lock.lock(); + this->m_acquireTime.stop(); + + this->m_criticalSectionTime.start(); + } + + void unlock() { + this->m_lock.unlock(); + this->m_criticalSectionTime.stop(); + } + }; +} +} From c9cf4b72de82e369cbcd30658864230fc8345750 Mon Sep 17 00:00:00 2001 From: Sven Czarnian Date: Sun, 23 Apr 2023 19:18:47 +0200 Subject: [PATCH 3/7] initialize all members --- com/Airport.cpp | 2 ++ 1 file changed, 2 insertions(+) diff --git a/com/Airport.cpp b/com/Airport.cpp index d455d77..463a050 100644 --- a/com/Airport.cpp +++ b/com/Airport.cpp @@ -16,6 +16,7 @@ Airport::Airport() : m_airport(), m_worker(), m_lock(), + m_pause(false), m_flights(), m_stop(false) { } @@ -23,6 +24,7 @@ Airport::Airport(const std::string& airport) : m_airport(airport), m_worker(), m_lock(), + m_pause(false), m_flights(), m_stop(false) { const auto flights = Server::instance().allFlights(this->m_airport); From fcf08d3f7be2d39e0cf63fb00b2281061fe26846 Mon Sep 17 00:00:00 2001 From: Sven Czarnian Date: Sun, 23 Apr 2023 19:19:41 +0200 Subject: [PATCH 4/7] use the performance lock --- com/Airport.cpp | 4 ++-- com/Airport.h | 4 +++- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/com/Airport.cpp b/com/Airport.cpp index 463a050..4c02ab4 100644 --- a/com/Airport.cpp +++ b/com/Airport.cpp @@ -15,16 +15,16 @@ static constexpr std::size_t FlightServer = 2; Airport::Airport() : m_airport(), m_worker(), - m_lock(), m_pause(false), + m_lock("EMPTY"), m_flights(), m_stop(false) { } Airport::Airport(const std::string& airport) : m_airport(airport), m_worker(), - m_lock(), m_pause(false), + m_lock(airport), m_flights(), m_stop(false) { const auto flights = Server::instance().allFlights(this->m_airport); diff --git a/com/Airport.h b/com/Airport.h index a016849..be6d3ec 100644 --- a/com/Airport.h +++ b/com/Airport.h @@ -10,6 +10,8 @@ #include +#include "PerformanceLock.h" + namespace vacdm { namespace com { @@ -24,7 +26,7 @@ class Airport { std::string m_airport; std::thread m_worker; volatile bool m_pause; - std::mutex m_lock; + PerformanceLock m_lock; std::map> m_flights; volatile bool m_stop; From 3e5af6f305918d6d459176bc7988a42522421b1f Mon Sep 17 00:00:00 2001 From: Sven Czarnian Date: Sun, 23 Apr 2023 19:20:12 +0200 Subject: [PATCH 5/7] extend the airport with more performance measurement --- com/Airport.cpp | 31 +++++++++++++++++++++++++++++-- com/Airport.h | 3 +++ 2 files changed, 32 insertions(+), 2 deletions(-) diff --git a/com/Airport.cpp b/com/Airport.cpp index 4c02ab4..76ed9f5 100644 --- a/com/Airport.cpp +++ b/com/Airport.cpp @@ -18,7 +18,10 @@ Airport::Airport() : m_pause(false), m_lock("EMPTY"), m_flights(), - m_stop(false) { } + m_stop(false), + m_manualUpdatePerformance("EMPTY"), + m_workerAllFlightsPerformance("EMPTY"), + m_workerUpdateFlightsPerformance("EMPTY") { } Airport::Airport(const std::string& airport) : m_airport(airport), @@ -26,7 +29,10 @@ Airport::Airport(const std::string& airport) : m_pause(false), m_lock(airport), m_flights(), - m_stop(false) { + m_stop(false), + m_manualUpdatePerformance("ManualUpdates" + airport), + m_workerAllFlightsPerformance("AllFlightsRequest" + airport), + m_workerUpdateFlightsPerformance("UpdateFlights" + airport) { const auto flights = Server::instance().allFlights(this->m_airport); for (const auto& flight : std::as_const(flights)) { this->m_flights.insert({ flight.callsign, { flight, types::Flight_t(), flight } }); @@ -86,6 +92,7 @@ void Airport::flightDisconnected(const std::string& callsign) { std::lock_guard guard(this->m_lock); + this->m_manualUpdatePerformance.start(); auto it = this->m_flights.find(callsign); if (it != this->m_flights.end() && it->second[FlightServer].callsign == callsign) { Json::Value root; @@ -97,6 +104,7 @@ void Airport::flightDisconnected(const std::string& callsign) { it->second[FlightEuroscope].inactive = true; } + this->m_manualUpdatePerformance.stop(); } std::string Airport::timestampToIsoString(const std::chrono::utc_clock::time_point& timepoint) { @@ -118,6 +126,7 @@ void Airport::updateExot(const std::string& callsign, const std::chrono::utc_clo std::lock_guard guard(this->m_lock); + this->m_manualUpdatePerformance.start(); auto it = this->m_flights.find(callsign); if (it != this->m_flights.end() && it->second[FlightServer].callsign == callsign) { Json::Value root; @@ -142,6 +151,8 @@ void Airport::updateExot(const std::string& callsign, const std::chrono::utc_clo logging::Logger::instance().log("Airport", logging::Logger::Level::Debug, "Updating EXOT: " + callsign + ", " + root["vacdm"]["exot"].asString()); Server::instance().patchFlight(callsign, root); } + + this->m_manualUpdatePerformance.stop(); } void Airport::updateTobt(const std::string& callsign, const std::chrono::utc_clock::time_point& tobt, bool manualTobt) { @@ -150,6 +161,7 @@ void Airport::updateTobt(const std::string& callsign, const std::chrono::utc_clo std::lock_guard guard(this->m_lock); + this->m_manualUpdatePerformance.start(); auto it = this->m_flights.find(callsign); if (it != this->m_flights.end() && it->second[FlightServer].callsign == callsign) { bool resetTsat = (tobt == types::defaultTime && true == manualTobt) || tobt >= it->second[FlightConsolidated].tsat; @@ -180,6 +192,7 @@ void Airport::updateTobt(const std::string& callsign, const std::chrono::utc_clo logging::Logger::instance().log("Airport", logging::Logger::Level::Debug, "Updating TOBT: " + callsign + ", " + root["vacdm"]["tobt"].asString()); Server::instance().patchFlight(callsign, root); } + this->m_manualUpdatePerformance.stop(); } void Airport::updateAsat(const std::string& callsign, const std::chrono::utc_clock::time_point& asat) { @@ -188,6 +201,7 @@ void Airport::updateAsat(const std::string& callsign, const std::chrono::utc_clo std::lock_guard guard(this->m_lock); + this->m_manualUpdatePerformance.start(); auto it = this->m_flights.find(callsign); if (it != this->m_flights.end() && it->second[FlightServer].callsign == callsign) { Json::Value root; @@ -202,6 +216,7 @@ void Airport::updateAsat(const std::string& callsign, const std::chrono::utc_clo logging::Logger::instance().log("Airport", logging::Logger::Level::Debug, "Updating ASAT: " + callsign + ", " + root["vacdm"]["asat"].asString()); Server::instance().patchFlight(callsign, root); } + this->m_manualUpdatePerformance.stop(); } void Airport::updateAobt(const std::string& callsign, const std::chrono::utc_clock::time_point& aobt) { @@ -210,6 +225,7 @@ void Airport::updateAobt(const std::string& callsign, const std::chrono::utc_clo std::lock_guard guard(this->m_lock); + this->m_manualUpdatePerformance.start(); auto it = this->m_flights.find(callsign); if (it != this->m_flights.end() && it->second[FlightServer].callsign == callsign) { Json::Value root; @@ -224,6 +240,7 @@ void Airport::updateAobt(const std::string& callsign, const std::chrono::utc_clo logging::Logger::instance().log("Airport", logging::Logger::Level::Debug, "Updating AOBT: " + callsign + ", " + root["vacdm"]["aobt"].asString()); Server::instance().patchFlight(callsign, root); } + this->m_manualUpdatePerformance.stop(); } void Airport::updateAtot(const std::string& callsign, const std::chrono::utc_clock::time_point& atot) { @@ -232,6 +249,7 @@ void Airport::updateAtot(const std::string& callsign, const std::chrono::utc_clo std::lock_guard guard(this->m_lock); + this->m_manualUpdatePerformance.start(); auto it = this->m_flights.find(callsign); if (it != this->m_flights.end() && it->second[FlightServer].callsign == callsign) { Json::Value root; @@ -246,6 +264,7 @@ void Airport::updateAtot(const std::string& callsign, const std::chrono::utc_clo logging::Logger::instance().log("Airport", logging::Logger::Level::Debug, "Updating ATOT: " + callsign + ", " + root["vacdm"]["atot"].asString()); Server::instance().patchFlight(callsign, root); } + this->m_manualUpdatePerformance.stop(); } void Airport::updateAsrt(const std::string& callsign, const std::chrono::utc_clock::time_point& asrt) { @@ -254,6 +273,7 @@ void Airport::updateAsrt(const std::string& callsign, const std::chrono::utc_clo std::lock_guard guard(this->m_lock); + this->m_manualUpdatePerformance.start(); auto it = this->m_flights.find(callsign); if (it != this->m_flights.end() && it->second[FlightServer].callsign == callsign) { Json::Value root; @@ -268,6 +288,7 @@ void Airport::updateAsrt(const std::string& callsign, const std::chrono::utc_clo logging::Logger::instance().log("Airport", logging::Logger::Level::Debug, "Updating ASRT: " + callsign + ", " + root["vacdm"]["asrt"].asString()); Server::instance().patchFlight(callsign, root); } + this->m_manualUpdatePerformance.stop(); } void Airport::updateAort(const std::string& callsign, const std::chrono::utc_clock::time_point& aort) { @@ -276,6 +297,7 @@ void Airport::updateAort(const std::string& callsign, const std::chrono::utc_clo std::lock_guard guard(this->m_lock); + this->m_manualUpdatePerformance.start(); auto it = this->m_flights.find(callsign); if (it != this->m_flights.end() && it->second[FlightServer].callsign == callsign) { Json::Value root; @@ -290,6 +312,7 @@ void Airport::updateAort(const std::string& callsign, const std::chrono::utc_clo logging::Logger::instance().log("Airport", logging::Logger::Level::Debug, "Updating AORT: " + callsign + ", " + root["vacdm"]["aort"].asString()); Server::instance().patchFlight(callsign, root); } + this->m_manualUpdatePerformance.stop(); } Airport::SendType Airport::deltaEuroscopeToBackend(const std::array& data, Json::Value& root) { @@ -440,9 +463,11 @@ void Airport::run() { if (true == this->m_pause) continue; + this->m_workerAllFlightsPerformance.start(); logging::Logger::instance().log("Airport", logging::Logger::Level::Debug, "New server update cycle"); auto flights = com::Server::instance().allFlights(this->m_airport); std::list> transmissionBuffer; + this->m_workerAllFlightsPerformance.stop(); this->m_lock.lock(); // check which updates are needed and update consolidated views based on the server @@ -494,12 +519,14 @@ void Airport::run() { this->m_lock.unlock(); // send the deltas + this->m_workerUpdateFlightsPerformance.start(); for (const auto& transmission : std::as_const(transmissionBuffer)) { if (std::get<1>(transmission) == Airport::SendType::Post) Server::instance().postFlight(std::get<2>(transmission)); else Server::instance().patchFlight(std::get<0>(transmission), std::get<2>(transmission)); } + this->m_workerUpdateFlightsPerformance.stop(); } } diff --git a/com/Airport.h b/com/Airport.h index be6d3ec..696cebb 100644 --- a/com/Airport.h +++ b/com/Airport.h @@ -29,6 +29,9 @@ class Airport { PerformanceLock m_lock; std::map> m_flights; volatile bool m_stop; + logging::Performance m_manualUpdatePerformance; + logging::Performance m_workerAllFlightsPerformance; + logging::Performance m_workerUpdateFlightsPerformance; static std::string timestampToIsoString(const std::chrono::utc_clock::time_point& timepoint); static SendType deltaEuroscopeToBackend(const std::array& data, Json::Value& root); From d7b5d55450d30d3aa4846a56b99233c620d7b2f5 Mon Sep 17 00:00:00 2001 From: Sven Czarnian Date: Sun, 23 Apr 2023 19:33:53 +0200 Subject: [PATCH 6/7] remove useless logging --- com/Airport.cpp | 2 -- 1 file changed, 2 deletions(-) diff --git a/com/Airport.cpp b/com/Airport.cpp index d455d77..19d0a62 100644 --- a/com/Airport.cpp +++ b/com/Airport.cpp @@ -477,8 +477,6 @@ void Airport::run() { const auto sendType = Airport::deltaEuroscopeToBackend(it->second, root); if (Airport::SendType::None != sendType) transmissionBuffer.push_back({ it->first, sendType, root }); - else - logging::Logger::instance().log("vACDM", logging::Logger::Level::Debug, "Don't update " + it->first); if (true == removeFlight) { logging::Logger::instance().log("vACDM", logging::Logger::Level::Debug, "Deleting " + it->first); From 605c50177ca983d56c2f969ef9434f90b3be5764 Mon Sep 17 00:00:00 2001 From: Sven Czarnian Date: Sun, 23 Apr 2023 19:34:10 +0200 Subject: [PATCH 7/7] validate that an update is required --- com/Airport.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/com/Airport.cpp b/com/Airport.cpp index 19d0a62..e76bdb2 100644 --- a/com/Airport.cpp +++ b/com/Airport.cpp @@ -379,7 +379,7 @@ Airport::SendType Airport::deltaEuroscopeToBackend(const std::array