strepsirrhini/libreoffice-online
3
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

wsd: more informative timestamps in dumpState

Browse source 
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 <ashod.nakashian@collabora.co.uk>
This commit is contained in:
Ashod Nakashian 2022-02-28 21:15:17 -05:00 committed by Ashod Nakashian
parent 319685d858
commit 832e308e8f
4 changed files with 71 additions and 30 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

19
common/Util.cpp
View file

@ -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<std::chrono::system_clock::duration>(
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()

52
common/Util.hpp
View file

@ -9,6 +9,7 @@
#include <cassert>
#include <cerrno>
#include <chrono>
#include <cinttypes>
#include <cstddef>
#include <cstdint>
@ -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 <typename Dst, typename Src, typename std::is_same<Src, Dst>::type>
Dst convertChronoClock(const Src time)
{
return std::chrono::time_point_cast<Dst>(time);
}
/// Converter between two different clocks,
/// such as system_clock and stead_clock.
/// Note: by nature this has limited accuracy.
template <typename Dst, typename Src, typename Enable = void>
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<typename Dst::duration>(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<std::chrono::system_clock::time_point>(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 <typename U, typename T> std::string getTimeForLog(const U& now, const T& time)
{
const auto elapsed = now - convertChronoClock<U>(time);
const auto elapsedS = std::chrono::duration_cast<std::chrono::seconds>(elapsed);
const auto elapsedMS =
std::chrono::duration_cast<std::chrono::milliseconds>(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

9
wsd/DocumentBroker.cpp
View file

@ -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<std::chrono::seconds>(
now - _threadStart).count() << 's';
os << "\n still loading... "
<< std::chrono::duration_cast<std::chrono::seconds>(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();

21
wsd/DocumentBroker.hpp
View file

@ -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: