diff --git a/CMakeLists.txt b/CMakeLists.txt index c20b539..23cdd1a 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -58,10 +58,12 @@ SET(SOURCE_FILES config/FileFormat.h com/Airport.cpp com/Airport.h + com/PerformanceLock.h com/Server.cpp com/Server.h logging/Logger.cpp logging/Logger.h + logging/Performance.h logging/sqlite3.c logging/sqlite3.h logging/sqlite3ext.h diff --git a/com/Airport.cpp b/com/Airport.cpp index d455d77..c0d5080 100644 --- a/com/Airport.cpp +++ b/com/Airport.cpp @@ -15,16 +15,24 @@ 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) { } + m_stop(false), + m_manualUpdatePerformance("EMPTY"), + m_workerAllFlightsPerformance("EMPTY"), + m_workerUpdateFlightsPerformance("EMPTY") { } Airport::Airport(const std::string& airport) : m_airport(airport), m_worker(), - m_lock(), + 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 } }); @@ -84,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; @@ -95,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) { @@ -116,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; @@ -140,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) { @@ -148,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; @@ -178,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) { @@ -186,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; @@ -200,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) { @@ -208,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; @@ -222,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) { @@ -230,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; @@ -244,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) { @@ -252,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; @@ -266,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) { @@ -274,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; @@ -288,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) { @@ -379,7 +404,7 @@ Airport::SendType Airport::deltaEuroscopeToBackend(const std::arraym_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 @@ -477,8 +504,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); @@ -492,12 +517,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 a016849..696cebb 100644 --- a/com/Airport.h +++ b/com/Airport.h @@ -10,6 +10,8 @@ #include +#include "PerformanceLock.h" + namespace vacdm { namespace com { @@ -24,9 +26,12 @@ 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; + 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); 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(); + } + }; +} +} 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 + } + }; +} +}