added debugging of usecTimestampNow() in octree server to better understand flight times

assignment-client/src/octree/OctreeServer.cpp

@@ -1017,6 +1017,9 @@ void OctreeServer::readConfiguration() {
     readOptionBool(QString("debugReceiving"), settingsSectionObject, _debugReceiving);
     qDebug("debugReceiving=%s", debug::valueOf(_debugReceiving));
 
+    readOptionBool(QString("debugTimestampNow"), settingsSectionObject, _debugTimestampNow);
+    qDebug() << "debugTimestampNow=" << _debugTimestampNow;
+
     bool noPersist;
     readOptionBool(QString("NoPersist"), settingsSectionObject, noPersist);
     _wantPersist = !noPersist;
@@ -1133,7 +1136,7 @@ void OctreeServer::run() {
 
         // now set up PersistThread
         _persistThread = new OctreePersistThread(_tree, _persistFilename, _persistInterval,
-                                    _wantBackup, _backupInterval, _backupExtensionFormat);
+                                    _wantBackup, _backupInterval, _backupExtensionFormat, _debugTimestampNow);
         if (_persistThread) {
             _persistThread->initialize(true);
         }

assignment-client/src/octree/OctreeServer.h

@@ -162,6 +162,7 @@ protected:
     bool _wantPersist;
     bool _debugSending;
     bool _debugReceiving;
+    bool _debugTimestampNow;
     bool _verboseDebug;
     JurisdictionMap* _jurisdiction;
     JurisdictionSender* _jurisdictionSender;

domain-server/resources/describe-settings.json

@@ -359,6 +359,13 @@
         "default": false,
         "advanced": true
       },
+      {
+        "name": "debugTimestampNow",
+        "type": "checkbox",
+        "help": "extra debugging for usecTimestampNow() function",
+        "default": false,
+        "advanced": true
+      },
       {
         "name": "clockSkew",
         "label": "Clock Skew",

libraries/octree/src/OctreePersistThread.cpp

@@ -22,8 +22,8 @@ const int OctreePersistThread::DEFAULT_BACKUP_INTERVAL = 1000 * 60 * 30; // ever
 const QString OctreePersistThread::DEFAULT_BACKUP_EXTENSION_FORMAT(".backup.%Y-%m-%d.%H:%M:%S.%z");
 
 
-OctreePersistThread::OctreePersistThread(Octree* tree, const QString& filename, int persistInterval, 
+OctreePersistThread::OctreePersistThread(Octree* tree, const QString& filename, int persistInterval, bool wantBackup, 
-                                                bool wantBackup, int backupInterval, const QString& backupExtensionFormat) :
+                                            int backupInterval, const QString& backupExtensionFormat, bool debugTimestampNow) :
     _tree(tree),
     _filename(filename),
     _backupExtensionFormat(backupExtensionFormat),
@@ -33,7 +33,9 @@ OctreePersistThread::OctreePersistThread(Octree* tree, const QString& filename,
     _loadTimeUSecs(0),
     _lastCheck(0),
     _lastBackup(0),
-    _wantBackup(wantBackup)
+    _wantBackup(wantBackup),
+    _debugTimestampNow(debugTimestampNow),
+    _lastTimeDebug(0)
 {
 }
 
@@ -101,6 +103,18 @@ bool OctreePersistThread::process() {
             persist();
         }
     }
+    
+    // if we were asked to debugTimestampNow do that now...
+    if (_debugTimestampNow) {
+        quint64 now = usecTimestampNow();
+        quint64 sinceLastDebug = now - _lastTimeDebug;
+        quint64 DEBUG_TIMESTAMP_INTERVAL = 600000000; // every 10 minutes
+
+        if (sinceLastDebug > DEBUG_TIMESTAMP_INTERVAL) {
+            _lastTimeDebug = usecTimestampNow(true); // ask for debug output
+        }
+        
+    }
     return isStillRunning();  // keep running till they terminate us
 }
 

libraries/octree/src/OctreePersistThread.h

@@ -28,7 +28,8 @@ public:
 
     OctreePersistThread(Octree* tree, const QString& filename, int persistInterval = DEFAULT_PERSIST_INTERVAL, 
                                 bool wantBackup = false, int backupInterval = DEFAULT_BACKUP_INTERVAL,
-                                const QString& backupExtensionFormat = DEFAULT_BACKUP_EXTENSION_FORMAT);
+                                const QString& backupExtensionFormat = DEFAULT_BACKUP_EXTENSION_FORMAT,
+                                bool debugTimestampNow = false);
 
     bool isInitialLoadComplete() const { return _initialLoadComplete; }
     quint64 getLoadElapsedTime() const { return _loadTimeUSecs; }
@@ -57,6 +58,9 @@ private:
     quint64 _lastBackup;
     bool _wantBackup;
     time_t _lastPersistTime;
+    
+    bool _debugTimestampNow;
+    quint64 _lastTimeDebug;
 };
 
 #endif // hifi_OctreePersistThread_h

libraries/shared/src/SharedUtil.cpp

@@ -37,7 +37,7 @@ void usecTimestampNowForceClockSkew(int clockSkew) {
     ::usecTimestampNowAdjust = clockSkew;
 }
 
-quint64 usecTimestampNow() {
+quint64 usecTimestampNow(bool wantDebug) {
     static bool usecTimestampNowIsInitialized = false;
     static qint64 TIME_REFERENCE = 0; // in usec
     static QElapsedTimer timestampTimer;
@@ -57,7 +57,6 @@ quint64 usecTimestampNow() {
             quint64 msecsElapsed = timestampTimer.restart();
             quint64 usecsElapsed = nsecsElapsed / 1000;  // nsec to usec
             TIME_REFERENCE += usecsElapsed;
-            const bool wantDebug = false;
             if (wantDebug) {
                 qDebug() << "usecTimestampNow() - resetting QElapsedTimer. ";
                 qDebug() << "    RESET_AFTER_ELAPSED_NSECS:" << RESET_AFTER_ELAPSED_NSECS;
@@ -68,8 +67,34 @@ quint64 usecTimestampNow() {
         }
     }
     
-    //          usec                       nsec to usec                   usec
+    quint64 nsecsElapsed = timestampTimer.nsecsElapsed();
-    return TIME_REFERENCE + timestampTimer.nsecsElapsed() / 1000 + ::usecTimestampNowAdjust;
+    quint64 usecsElapsed = nsecsElapsed / 1000;  // nsec to usec
+    quint64 now = TIME_REFERENCE + usecsElapsed + ::usecTimestampNowAdjust;
+    
+    if (wantDebug) {
+        QDateTime currentLocalTime = QDateTime::currentDateTime();
+
+        quint64 msecsNow = now / 1000; // usecs to msecs
+        QDateTime nowAsString;
+        nowAsString.setMSecsSinceEpoch(msecsNow);
+
+        quint64 msecsTimeReference = TIME_REFERENCE / 1000; // usecs to msecs
+        QDateTime timeReferenceAsString;
+        timeReferenceAsString.setMSecsSinceEpoch(msecsTimeReference);
+
+        qDebug() << "usecTimestampNow() - details... ";
+        qDebug() << "           TIME_REFERENCE:" << TIME_REFERENCE;
+        qDebug() << "    timeReferenceAsString:" << timeReferenceAsString.toString("yyyy-MM-dd hh:mm:ss.zzz");
+        qDebug() << "   usecTimestampNowAdjust:" << usecTimestampNowAdjust;
+        qDebug() << "             nsecsElapsed:" << nsecsElapsed;
+        qDebug() << "             usecsElapsed:" << usecsElapsed;
+        qDebug() << "                      now:" << now;
+        qDebug() << "                 msecsNow:" << msecsNow;
+        qDebug() << "              nowAsString:" << nowAsString.toString("yyyy-MM-dd hh:mm:ss.zzz");
+        qDebug() << "         currentLocalTime:" << currentLocalTime.toString("yyyy-MM-dd hh:mm:ss.zzz");
+    }
+    
+    return now;
 }
 
 float randFloat() {

libraries/shared/src/SharedUtil.h

@@ -67,7 +67,7 @@ static const quint64 USECS_PER_SECOND = USECS_PER_MSEC * MSECS_PER_SECOND;
 
 const int BITS_IN_BYTE  = 8;
 
-quint64 usecTimestampNow();
+quint64 usecTimestampNow(bool wantDebug = false);
 void usecTimestampNowForceClockSkew(int clockSkew);
 
 float randFloat();