From 832e308e8fd5bd576343268e118b6e870e830ca1 Mon Sep 17 00:00:00 2001 From: Ashod Nakashian Date: Mon, 28 Feb 2022 21:15:17 -0500 Subject: [PATCH] wsd: more informative timestamps in dumpState The timestamps now helpfully include how long ago they were. This also improves the conversion between chrono clocks by adding generic functions. Change-Id: I18081330564c8d969b9364cf1b9e33546e241280 Signed-off-by: Ashod Nakashian --- common/Util.cpp | 19 ++++----------- common/Util.hpp | 52 +++++++++++++++++++++++++++++++++++++++++- wsd/DocumentBroker.cpp | 9 ++++---- wsd/DocumentBroker.hpp | 21 +++++++++-------- 4 files changed, 71 insertions(+), 30 deletions(-) diff --git a/common/Util.cpp b/common/Util.cpp index 2e0948c33..ba8cc8c5b 100644 --- a/common/Util.cpp +++ b/common/Util.cpp @@ -940,20 +940,11 @@ namespace Util localtime_r(&t, &tm); char buffer[128] = { 0 }; - const size_t offset = std::strftime(buffer, 80, "%a %b %d %H:%M", &tm); - sprintf(&buffer[offset], ".%3d %d", msFraction, tm.tm_year + 1900); - return std::string(buffer); - } - - /// Returns the given time_point as string in the local time. - /// Format: Thu Jan 27 03:45:27.123 2022 - std::string getSteadyClockAsString(const std::chrono::steady_clock::time_point &time) - { - const std::chrono::system_clock::time_point corrected = - std::chrono::system_clock::now() + - std::chrono::duration_cast( - time - std::chrono::steady_clock::now()); - return getSystemClockAsString(corrected); + std::strftime(buffer, 80, "%a %b %d %H:%M", &tm); + std::stringstream ss; + ss << buffer << '.' << std::setfill('0') << std::setw(3) << msFraction << ' ' + << tm.tm_year + 1900; + return ss.str(); } bool isFuzzing() diff --git a/common/Util.hpp b/common/Util.hpp index ca7fb1598..70488e8d5 100644 --- a/common/Util.hpp +++ b/common/Util.hpp @@ -9,6 +9,7 @@ #include #include +#include #include #include #include @@ -1224,13 +1225,62 @@ int main(int argc, char**argv) /// Convert time from ISO8061 fraction format std::chrono::system_clock::time_point iso8601ToTimestamp(const std::string& iso8601Time, const std::string& logName); + /// A null-converter between two identical clocks. + template ::type> + Dst convertChronoClock(const Src time) + { + return std::chrono::time_point_cast(time); + } + + /// Converter between two different clocks, + /// such as system_clock and stead_clock. + /// Note: by nature this has limited accuracy. + template + Dst convertChronoClock(const Src time) + { + const auto before = Src::clock::now(); + const auto now = Dst::clock::now(); + const auto after = Src::clock::now(); + const auto diff = after - before; + const auto correction = before + (diff / 2); + return std::chrono::time_point_cast(now + (time - correction)); + } + /// Converts from system_clock to string for debugging / tracing. /// Format (local time): Thu Jan 27 03:45:27.123 2022 std::string getSystemClockAsString(const std::chrono::system_clock::time_point &time); /// conversion from steady_clock for debugging / tracing /// Format (local time): Thu Jan 27 03:45:27.123 2022 - std::string getSteadyClockAsString(const std::chrono::steady_clock::time_point &time); + inline std::string getSteadyClockAsString(const std::chrono::steady_clock::time_point& time) + { + return getSystemClockAsString( + convertChronoClock(time)); + } + + /// See getSystemClockAsString. + inline std::string getClockAsString(const std::chrono::system_clock::time_point& time) + { + return getSystemClockAsString(time); + } + + /// See getSteadyClockAsString. + inline std::string getClockAsString(const std::chrono::steady_clock::time_point& time) + { + return getSteadyClockAsString(time); + } + + template std::string getTimeForLog(const U& now, const T& time) + { + const auto elapsed = now - convertChronoClock(time); + const auto elapsedS = std::chrono::duration_cast(elapsed); + const auto elapsedMS = + std::chrono::duration_cast(elapsed) - elapsedS; + + std::stringstream ss; + ss << getClockAsString(time) << " (" << elapsedS << ' ' << elapsedMS << " ago)"; + return ss.str(); + } /** * Avoid using the configuration layer and rely on defaults which is only useful for special diff --git a/wsd/DocumentBroker.cpp b/wsd/DocumentBroker.cpp index 07edc275b..906e244ca 100644 --- a/wsd/DocumentBroker.cpp +++ b/wsd/DocumentBroker.cpp @@ -3446,7 +3446,7 @@ void DocumentBroker::dumpState(std::ostream& os) uint64_t sent = 0, recv = 0; getIOStats(sent, recv); - auto now = std::chrono::steady_clock::now(); + const auto now = std::chrono::steady_clock::now(); os << std::boolalpha; os << " Broker: " << COOLWSD::anonymizeUrl(_filename) << " pid: " << getPid(); @@ -3457,9 +3457,8 @@ void DocumentBroker::dumpState(std::ostream& os) if (isLoaded()) os << "\n loaded in: " << _loadDuration; else - os << "\n still loading... " << - std::chrono::duration_cast( - now - _threadStart).count() << 's'; + os << "\n still loading... " + << std::chrono::duration_cast(now - _threadStart); os << "\n sent: " << sent; os << "\n recv: " << recv; os << "\n jail id: " << _jailId; @@ -3469,7 +3468,7 @@ void DocumentBroker::dumpState(std::ostream& os) os << "\n doc key: " << _docKey; os << "\n doc id: " << _docId; os << "\n num sessions: " << _sessions.size(); - os << "\n thread start: " << Util::getSteadyClockAsString(_threadStart); + os << "\n thread start: " << Util::getTimeForLog(now, _threadStart); os << "\n modified?: " << isModified(); os << "\n possibly-modified: " << isPossiblyModified(); os << "\n haveActivityAfterSaveRequest: " << haveActivityAfterSaveRequest(); diff --git a/wsd/DocumentBroker.hpp b/wsd/DocumentBroker.hpp index ce9955fbf..75727d1b9 100644 --- a/wsd/DocumentBroker.hpp +++ b/wsd/DocumentBroker.hpp @@ -825,23 +825,24 @@ private: void dumpState(std::ostream& os, const std::string& indent = "\n ") { + const auto now = std::chrono::steady_clock::now(); os << indent << "isSaving now: " << std::boolalpha << isSaving(); os << indent << "auto-save enabled: " << std::boolalpha << _isAutosaveEnabled; os << indent << "auto-save interval: " << _autosaveInterval; - os << indent << "last auto-save check time: " - << Util::getSteadyClockAsString(_lastAutosaveCheckTime); + os << indent + << "last auto-save check time: " << Util::getTimeForLog(now, _lastAutosaveCheckTime); os << indent << "auto-save check needed: " << std::boolalpha << needAutosaveCheck(); os << indent - << "last save request: " << Util::getSteadyClockAsString(lastSaveRequestTime()); + << "last save request: " << Util::getTimeForLog(now, lastSaveRequestTime()); os << indent - << "last save response: " << Util::getSteadyClockAsString(lastSaveResponseTime()); + << "last save response: " << Util::getTimeForLog(now, lastSaveResponseTime()); os << indent << "since last save request: " << timeSinceLastSaveRequest(); os << indent << "since last save response: " << timeSinceLastSaveResponse(); os << indent - << "file last modified time: " << Util::getSystemClockAsString(_lastModifiedTime); + << "file last modified time: " << Util::getTimeForLog(now, _lastModifiedTime); os << indent << "last save timed-out: " << std::boolalpha << hasSavingTimedOut(); os << indent << "last save successful: " << lastSaveSuccessful(); os << indent << "save failure count: " << saveFailureCount(); @@ -951,14 +952,14 @@ private: void dumpState(std::ostream& os, const std::string& indent = "\n ") { - os << indent - << "last upload time: " << Util::getSteadyClockAsString(getLastUploadTime()); + const auto now = std::chrono::steady_clock::now(); + os << indent << "last upload time: " << Util::getTimeForLog(now, getLastUploadTime()); os << indent << "last upload was successful: " << lastUploadSuccessful(); os << indent << "upload failure count: " << uploadFailureCount(); os << indent << "last modified time: " << _lastModifiedTime; - os << indent << "last upload time: " << Util::getSteadyClockAsString(_lastUploadTime); - os << indent << "file last modified: " - << Util::getSystemClockAsString(_lastUploadedFileModifiedTime); + os << indent << "last upload time: " << Util::getTimeForLog(now, _lastUploadTime); + os << indent + << "file last modified: " << Util::getTimeForLog(now, _lastUploadedFileModifiedTime); } private: