Fix printing of duration

TheOneRing · TheOneRing · commit 44f7f138a39e · 2025-07-18T13:34:36.000+02:00
Qt nowadays brings its own debug operator for std::chrono::duration, ensure we format it when needed
diff --git a/src/gui/accountstate.cpp b/src/gui/accountstate.cpp
@@ -449,7 +449,7 @@ void AccountState::slotConnectionValidatorResult(ConnectionValidator::Status sta
             QTimer::singleShot(_maintenanceToConnectedDelay + 100ms, this, [this] { AccountState::checkConnectivity(false); });
             return;
         } else if (_timeSinceMaintenanceOver.duration() < _maintenanceToConnectedDelay) {
-            qCInfo(lcAccountState) << "AccountState reconnection: only" << _timeSinceMaintenanceOver.duration() << "ms have passed";
+            qCInfo(lcAccountState) << "AccountState reconnection: only" << _timeSinceMaintenanceOver;
             return;
         }
     }
diff --git a/src/gui/connectionvalidator.cpp b/src/gui/connectionvalidator.cpp
@@ -50,7 +50,7 @@ ConnectionValidator::ConnectionValidator(AccountPtr account, QObject *parent)
     auto timer = new QTimer(this);
     timer->setInterval(30s);
     connect(timer, &QTimer::timeout, this,
-        [this] { qCInfo(lcConnectionValidator) << "ConnectionValidator" << _account->displayNameWithHost() << "still running after" << _duration.duration(); });
+        [this] { qCInfo(lcConnectionValidator) << "ConnectionValidator" << _account->displayNameWithHost() << "still running after" << _duration; });
     timer->start();
 }
 
@@ -201,7 +201,7 @@ void ConnectionValidator::reportResult(Status status)
 {
     if (OC_ENSURE(!_finished)) {
         _finished = true;
-        qCDebug(lcConnectionValidator) << status << _duration.duration();
+        qCDebug(lcConnectionValidator) << status << _duration;
         Q_EMIT connectionResult(status, _errors);
         deleteLater();
     }
diff --git a/src/libsync/common/checksums.cpp b/src/libsync/common/checksums.cpp
@@ -285,9 +285,9 @@ QByteArray ComputeChecksum::computeNow(QIODevice *device, CheckSums::Algorithm a
     // const cast to prevent stream to "device"
     const auto log = qScopeGuard([device, algorithm, timer = Utility::ChronoElapsedTimer()] {
         if (auto file = qobject_cast<QFile *>(device)) {
-            qCDebug(lcChecksums) << "Finished" << algorithm << "computation for" << file->fileName() << timer.duration();
+            qCDebug(lcChecksums) << "Finished" << algorithm << "computation for" << file->fileName() << timer;
         } else {
-            qCDebug(lcChecksums) << "Finished" << algorithm << "computation for" << device << timer.duration();
+            qCDebug(lcChecksums) << "Finished" << algorithm << "computation for" << device << timer;
         }
     });
     switch (algorithm) {
diff --git a/src/libsync/common/chronoelapsedtimer.cpp b/src/libsync/common/chronoelapsedtimer.cpp
@@ -20,9 +20,10 @@
 #include <QtGlobal>
 
 using namespace OCC::Utility;
+using namespace std::chrono;
 
 ChronoElapsedTimer::ChronoElapsedTimer(bool start)
-    : _start(std::chrono::steady_clock::now())
+    : _start(steady_clock::now())
     , _started(start)
 {
 }
@@ -34,26 +35,38 @@ bool ChronoElapsedTimer::isStarted() const
 
 void ChronoElapsedTimer::reset()
 {
-    _start = std::chrono::steady_clock::now();
+    _start = steady_clock::now();
     _end = {};
     _started = true;
 }
 
 void ChronoElapsedTimer::stop()
 {
-    Q_ASSERT(_end == std::chrono::steady_clock::time_point{});
+    Q_ASSERT(_end == steady_clock::time_point{});
     Q_ASSERT(_started);
-    _end = std::chrono::steady_clock::now();
+    _end = steady_clock::now();
     _started = false;
 }
 
-std::chrono::nanoseconds ChronoElapsedTimer::duration() const
+nanoseconds ChronoElapsedTimer::duration() const
 {
     if (!_started) {
-        return std::chrono::nanoseconds::max();
+        return nanoseconds::max();
     }
-    if (_end != std::chrono::steady_clock::time_point{}) {
+    if (_end != steady_clock::time_point{}) {
         return _end - _start;
     }
-    return std::chrono::steady_clock::now() - _start;
+    return steady_clock::now() - _start;
+}
+
+QDebug operator<<(QDebug debug, const ChronoElapsedTimer &timer)
+{
+    QDebugStateSaver save(debug);
+    debug.nospace();
+    auto duration = timer.duration();
+    const auto h = duration_cast<hours>(duration);
+    const auto min = duration_cast<minutes>(duration -= h);
+    const auto s = duration_cast<seconds>(duration -= min);
+    const auto ms = duration_cast<milliseconds>(duration -= s);
+    return debug << "ChronoElapsedTimer(" << h.count() << "h, " << min.count() << "min, " << s.count() << "s, " << ms.count() << "ms)";
 }
diff --git a/src/libsync/common/chronoelapsedtimer.h b/src/libsync/common/chronoelapsedtimer.h
@@ -18,6 +18,8 @@
 #pragma once
 #include "libsync/opencloudsynclib.h"
 
+#include <QDebug>
+
 #include <chrono>
 
 namespace OCC::Utility {
@@ -52,3 +54,5 @@ class OPENCLOUD_SYNC_EXPORT ChronoElapsedTimer
 };
 
 }
+
+OPENCLOUD_SYNC_EXPORT QDebug operator<<(QDebug debug, const OCC::Utility::ChronoElapsedTimer &in);
diff --git a/src/libsync/creds/credentialmanager.cpp b/src/libsync/creds/credentialmanager.cpp
@@ -75,14 +75,14 @@ QKeychain::Job *CredentialManager::set(const QString &key, const QVariant &data)
 
     Utility::ChronoElapsedTimer elapsedTimer;
     connect(timer, &QTimer::timeout, writeJob,
-        [writeJob, elapsedTimer] { qCWarning(lcCredentialsManager) << "set" << writeJob->key() << "has not yet finished." << elapsedTimer.duration(); });
+        [writeJob, elapsedTimer] { qCWarning(lcCredentialsManager) << "set" << writeJob->key() << "has not yet finished." << elapsedTimer; });
     connect(writeJob, &QKeychain::WritePasswordJob::finished, this, [writeJob, key, elapsedTimer, this] {
         if (writeJob->error() == QKeychain::NoError) {
-            qCInfo(lcCredentialsManager) << "added" << writeJob->key() << "after" << elapsedTimer.duration();
+            qCInfo(lcCredentialsManager) << "added" << writeJob->key() << "after" << elapsedTimer;
             // just a list, the values don't matter
             credentialsList().setValue(key, true);
         } else {
-            qCWarning(lcCredentialsManager) << "Failed to set:" << writeJob->key() << writeJob->errorString() << "after" << elapsedTimer.duration();
+            qCWarning(lcCredentialsManager) << "Failed to set:" << writeJob->key() << writeJob->errorString() << "after" << elapsedTimer;
         }
     });
     writeJob->setBinaryData(QCborValue::fromVariant(data).toCbor());
diff --git a/src/libsync/httplogger.cpp b/src/libsync/httplogger.cpp
@@ -90,7 +90,7 @@ void logHttp(const QByteArray &verb, HttpContext *ctx, QJsonObject &&header, QIO
             {QStringLiteral("cached"), reply->attribute(QNetworkRequest::SourceIsFromCacheAttribute).toBool()},
             // downcast to int, this is json
             {QStringLiteral("duration"), static_cast<int>(duration_cast<milliseconds>(ctx->timer.duration()).count())}, //
-            {QStringLiteral("durationString"), QDebug::toString(ctx->timer.duration())},
+            {QStringLiteral("durationString"), QDebug::toString(ctx->timer)},
             {QStringLiteral("version"),
                 QStringLiteral("HTTP %1").arg(
                     reply->attribute(QNetworkRequest::Http2WasUsedAttribute).toBool() ? QStringLiteral("1.1") : QStringLiteral("2"))}};
diff --git a/src/libsync/syncengine.cpp b/src/libsync/syncengine.cpp
@@ -379,7 +379,7 @@ void SyncEngine::startSync()
         return;
     }
 
-    qCInfo(lcEngine) << "#### Discovery start ####################################################" << _duration.duration();
+    qCInfo(lcEngine) << "#### Discovery start ####################################################" << _duration;
     qCInfo(lcEngine) << "Server" << account()->capabilities().status().versionString()
                      << (account()->isHttp2Supported() ? "Using HTTP/2" : "");
     _progressInfo->_status = ProgressInfo::Discovery;
@@ -470,7 +470,7 @@ void SyncEngine::slotDiscoveryFinished()
         return;
     }
 
-    qCInfo(lcEngine) << "#### Discovery end ####################################################" << _duration.duration();
+    qCInfo(lcEngine) << "#### Discovery end ####################################################" << _duration;
 
     // Sanity check
     if (!_journal->open()) {
@@ -537,14 +537,14 @@ void SyncEngine::slotDiscoveryFinished()
             erase_if(_syncItems, [&names](const SyncFileItemPtr &i) { return !names.contains(QStringView{i->localName()}); });
         }
 
-        qCInfo(lcEngine) << "#### Reconcile (aboutToPropagate) ####################################################" << _duration.duration();
+        qCInfo(lcEngine) << "#### Reconcile (aboutToPropagate) ####################################################" << _duration;
 
         _localDiscoveryPaths.clear();
 
         // To announce the beginning of the sync
         Q_EMIT aboutToPropagate(_syncItems);
 
-        qCInfo(lcEngine) << "#### Reconcile (aboutToPropagate OK) ####################################################" << _duration.duration();
+        qCInfo(lcEngine) << "#### Reconcile (aboutToPropagate OK) ####################################################" << _duration;
 
         // it's important to do this before ProgressInfo::start(), to announce start of new sync
         _progressInfo->_status = ProgressInfo::Propagation;
@@ -582,7 +582,7 @@ void SyncEngine::slotDiscoveryFinished()
         _propagator->start(std::move(_syncItems));
 
 
-        qCInfo(lcEngine) << "#### Post-Reconcile end ####################################################" << _duration.duration();
+        qCInfo(lcEngine) << "#### Post-Reconcile end ####################################################" << _duration;
     };
 
     finish();
@@ -656,7 +656,7 @@ void SyncEngine::slotPropagationFinished(bool success)
 
 void SyncEngine::finalize(bool success)
 {
-    qCInfo(lcEngine) << "Sync run for" << _localPath << "took" << _duration.duration();
+    qCInfo(lcEngine) << "Sync run for" << _localPath << "took" << _duration;
     _duration.stop();
 
     if (_discoveryPhase) {

Original file line number	Diff line number	Diff line change
`@@ -449,7 +449,7 @@ void AccountState::slotConnectionValidatorResult(ConnectionValidator::Status sta`
`449`	`449`	`QTimer::singleShot(_maintenanceToConnectedDelay + 100ms, this, [this] { AccountState::checkConnectivity(false); });`
`450`	`450`	`return;`
`451`	`451`	`} else if (_timeSinceMaintenanceOver.duration() < _maintenanceToConnectedDelay) {`
`452`		`- qCInfo(lcAccountState) << "AccountState reconnection: only" << _timeSinceMaintenanceOver.duration() << "ms have passed";`
	`452`	`+ qCInfo(lcAccountState) << "AccountState reconnection: only" << _timeSinceMaintenanceOver;`
`453`	`453`	`return;`
`454`	`454`	`}`
`455`	`455`	`}`
Original file line number	Diff line number	Diff line change
`@@ -50,7 +50,7 @@ ConnectionValidator::ConnectionValidator(AccountPtr account, QObject *parent)`
`50`	`50`	`auto timer = new QTimer(this);`
`51`	`51`	`timer->setInterval(30s);`
`52`	`52`	`connect(timer, &QTimer::timeout, this,`
`53`		`- [this] { qCInfo(lcConnectionValidator) << "ConnectionValidator" << _account->displayNameWithHost() << "still running after" << _duration.duration(); });`
	`53`	`+ [this] { qCInfo(lcConnectionValidator) << "ConnectionValidator" << _account->displayNameWithHost() << "still running after" << _duration; });`
`54`	`54`	`timer->start();`
`55`	`55`	`}`
`56`	`56`
`@@ -201,7 +201,7 @@ void ConnectionValidator::reportResult(Status status)`
`201`	`201`	`{`
`202`	`202`	`if (OC_ENSURE(!_finished)) {`
`203`	`203`	`_finished = true;`
`204`		`- qCDebug(lcConnectionValidator) << status << _duration.duration();`
	`204`	`+ qCDebug(lcConnectionValidator) << status << _duration;`
`205`	`205`	`Q_EMIT connectionResult(status, _errors);`
`206`	`206`	`deleteLater();`
`207`	`207`	`}`
Original file line number	Diff line number	Diff line change
`@@ -20,9 +20,10 @@`
`20`	`20`	`#include <QtGlobal>`
`21`	`21`
`22`	`22`	`using namespace OCC::Utility;`
	`23`	`+using namespace std::chrono;`
`23`	`24`
`24`	`25`	`ChronoElapsedTimer::ChronoElapsedTimer(bool start)`
`25`		`- : _start(std::chrono::steady_clock::now())`
	`26`	`+ : _start(steady_clock::now())`
`26`	`27`	`, _started(start)`
`27`	`28`	`{`
`28`	`29`	`}`
`@@ -34,26 +35,38 @@ bool ChronoElapsedTimer::isStarted() const`
`34`	`35`
`35`	`36`	`void ChronoElapsedTimer::reset()`
`36`	`37`	`{`
`37`		`- _start = std::chrono::steady_clock::now();`
	`38`	`+ _start = steady_clock::now();`
`38`	`39`	`_end = {};`
`39`	`40`	`_started = true;`
`40`	`41`	`}`
`41`	`42`
`42`	`43`	`void ChronoElapsedTimer::stop()`
`43`	`44`	`{`
`44`		`- Q_ASSERT(_end == std::chrono::steady_clock::time_point{});`
	`45`	`+ Q_ASSERT(_end == steady_clock::time_point{});`
`45`	`46`	`Q_ASSERT(_started);`
`46`		`- _end = std::chrono::steady_clock::now();`
	`47`	`+ _end = steady_clock::now();`
`47`	`48`	`_started = false;`
`48`	`49`	`}`
`49`	`50`
`50`		`-std::chrono::nanoseconds ChronoElapsedTimer::duration() const`
	`51`	`+nanoseconds ChronoElapsedTimer::duration() const`
`51`	`52`	`{`
`52`	`53`	`if (!_started) {`
`53`		`- return std::chrono::nanoseconds::max();`
	`54`	`+ return nanoseconds::max();`
`54`	`55`	`}`
`55`		`- if (_end != std::chrono::steady_clock::time_point{}) {`
	`56`	`+ if (_end != steady_clock::time_point{}) {`
`56`	`57`	`return _end - _start;`
`57`	`58`	`}`
`58`		`- return std::chrono::steady_clock::now() - _start;`
	`59`	`+ return steady_clock::now() - _start;`
	`60`	`+}`
	`61`	`+`
	`62`	`+QDebug operator<<(QDebug debug, const ChronoElapsedTimer &timer)`
	`63`	`+{`
	`64`	`+ QDebugStateSaver save(debug);`
	`65`	`+ debug.nospace();`
	`66`	`+ auto duration = timer.duration();`
	`67`	`+ const auto h = duration_cast<hours>(duration);`
	`68`	`+ const auto min = duration_cast<minutes>(duration -= h);`
	`69`	`+ const auto s = duration_cast<seconds>(duration -= min);`
	`70`	`+ const auto ms = duration_cast<milliseconds>(duration -= s);`
	`71`	`+ return debug << "ChronoElapsedTimer(" << h.count() << "h, " << min.count() << "min, " << s.count() << "s, " << ms.count() << "ms)";`
`59`	`72`	`}`