Move to doubles for all latency reporting metrics

11 files changed, 42 insertions, 32 deletions

diff --git a/storage/src/vespa/storage/bucketdb/bucketmanager.cpp b/storage/src/vespa/storage/bucketdb/bucketmanager.cpp
index 109db0a7c0f..8771d9cf174 100644
--- a/storage/src/vespa/storage/bucketdb/bucketmanager.cpp
+++ b/storage/src/vespa/storage/bucketdb/bucketmanager.cpp
@@ -609,7 +609,8 @@ BucketManager::processRequestBucketInfoCommands(BIList& reqs)
         _component.getBucketDatabase().chunkedAll(builder,
                         "BucketManager::processRequestBucketInfoCommands-2");
     }
-    _metrics->fullBucketInfoLatency.addValue(runStartTime);
+    _metrics->fullBucketInfoLatency.addValue(
+            runStartTime.getElapsedTimeAsDouble());
     for (auto& nodeAndCmd : requests) {
         auto reply(std::make_shared<api::RequestBucketInfoReply>(
                 *nodeAndCmd.second));
diff --git a/storage/src/vespa/storage/bucketdb/storagebucketdbinitializer.cpp b/storage/src/vespa/storage/bucketdb/storagebucketdbinitializer.cpp
index bc78f3786f6..023dd31747a 100644
--- a/storage/src/vespa/storage/bucketdb/storagebucketdbinitializer.cpp
+++ b/storage/src/vespa/storage/bucketdb/storagebucketdbinitializer.cpp
@@ -666,7 +666,7 @@ StorageBucketDBInitializer::checkIfDone()
     }
     _state._doneInitializing = true;
     _system._doneInitializeHandler.notifyDoneInitializing();
-    _metrics._initLatency.addValue(_metrics._startTime);
+    _metrics._initLatency.addValue(_metrics._startTime.getElapsedTimeAsDouble());
     LOG(debug, "Completed initializing");
 }
 
@@ -761,7 +761,7 @@ StorageBucketDBInitializer::handleListingCompleted()
     }
     LOG(info, "Completed listing buckets from disk. Minimum used bits is %u",
         _system._component.getMinUsedBitsTracker().getMinUsedBits());
-    _metrics._listLatency.addValue(_metrics._startTime);
+    _metrics._listLatency.addValue(_metrics._startTime.getElapsedTimeAsDouble());
 }
 
 double
diff --git a/storage/src/vespa/storage/distributor/distributor.cpp b/storage/src/vespa/storage/distributor/distributor.cpp
index 2dd42dbc817..d1e64406ef6 100644
--- a/storage/src/vespa/storage/distributor/distributor.cpp
+++ b/storage/src/vespa/storage/distributor/distributor.cpp
@@ -421,7 +421,8 @@ Distributor::leaveRecoveryMode()
 {
     if (isInRecoveryMode()) {
         LOG(debug, "Leaving recovery mode");
-        _metrics->recoveryModeTime.addValue(_recoveryTimeStarted);
+        _metrics->recoveryModeTime.addValue(
+                _recoveryTimeStarted.getElapsedTimeAsDouble());
     }
     _schedulingMode = MaintenanceScheduler::NORMAL_SCHEDULING_MODE;
 }
diff --git a/storage/src/vespa/storage/persistence/filestorage/filestormetrics.cpp b/storage/src/vespa/storage/persistence/filestorage/filestormetrics.cpp
index 73e187f7f1e..de0d3c464c9 100644
--- a/storage/src/vespa/storage/persistence/filestorage/filestormetrics.cpp
+++ b/storage/src/vespa/storage/persistence/filestorage/filestormetrics.cpp
@@ -154,7 +154,7 @@ FileStorDiskMetrics::FileStorDiskMetrics(const std::string& name,
     : MetricSet(name, "partofsum disk", description, owner, "disk"),
       sum("allthreads", "sum", "", this),
       queueSize("queuesize", "", "Size of input message queue.", this),
-      averageQueueWaitingTime(loadTypes, metrics::LongAverageMetric(
+      averageQueueWaitingTime(loadTypes, metrics::DoubleAverageMetric(
               "averagequeuewait", "",
               "Average time an operation spends in input queue."), this),
       pendingMerges("pendingmerge", "", "Number of buckets currently being merged.", this),
diff --git a/storage/src/vespa/storage/persistence/filestorage/filestormetrics.h b/storage/src/vespa/storage/persistence/filestorage/filestormetrics.h
index 5d4b9f618e3..8d4aa670cc6 100644
--- a/storage/src/vespa/storage/persistence/filestorage/filestormetrics.h
+++ b/storage/src/vespa/storage/persistence/filestorage/filestormetrics.h
@@ -22,7 +22,7 @@ struct FileStorThreadMetrics : public metrics::MetricSet
     struct Op : public metrics::MetricSet {
         std::string _name;
         metrics::LongCountMetric count;
-        metrics::LongAverageMetric latency;
+        metrics::DoubleAverageMetric latency;
         metrics::LongCountMetric failed;
 
         Op(const std::string& id, const std::string name, MetricSet* owner = 0);
@@ -114,10 +114,10 @@ public:
     std::vector<FileStorThreadMetrics::SP> threads;
     metrics::SumMetric<MetricSet> sum;
     metrics::LongAverageMetric queueSize;
-    metrics::LoadMetric<metrics::LongAverageMetric> averageQueueWaitingTime;
+    metrics::LoadMetric<metrics::DoubleAverageMetric> averageQueueWaitingTime;
     metrics::LongAverageMetric pendingMerges;
     metrics::DoubleAverageMetric waitingForLockHitRate;
-    metrics::LongAverageMetric lockWaitTime;
+    metrics::DoubleAverageMetric lockWaitTime;
 
     FileStorDiskMetrics(const std::string& name, const std::string& description,
                         const metrics::LoadTypeSet& loadTypes, MetricSet* owner);
diff --git a/storage/src/vespa/storage/persistence/mergehandler.cpp b/storage/src/vespa/storage/persistence/mergehandler.cpp
index 63e3ac1dcde..878c0f13ed0 100644
--- a/storage/src/vespa/storage/persistence/mergehandler.cpp
+++ b/storage/src/vespa/storage/persistence/mergehandler.cpp
@@ -911,7 +911,8 @@ MergeHandler::processBucketMerge(const spi::Bucket& bucket, MergeStatus& status,
     if (applyDiffNeedLocalData(cmd->getDiff(), 0, true)) {
         framework::MilliSecTimer startTime(_env._component.getClock());
         fetchLocalData(bucket, cmd->getLoadType(), cmd->getDiff(), 0, context);
-        _env._metrics.mergeDataReadLatency.addValue(startTime);
+        _env._metrics.mergeDataReadLatency.addValue(
+                startTime.getElapsedTimeAsDouble());
     }
     status.pendingId = cmd->getMsgId();
     LOG(debug, "Sending %s", cmd->toString().c_str());
@@ -1019,7 +1020,8 @@ MergeHandler::handleMergeBucket(api::MergeBucketCommand& cmd,
                      "Bucket not found in buildBucketInfo step");
         return tracker;
     }
-    _env._metrics.mergeMetadataReadLatency.addValue(s->startTime);
+    _env._metrics.mergeMetadataReadLatency.addValue(
+            s->startTime.getElapsedTimeAsDouble());
     LOG(spam, "Sending GetBucketDiff %" PRIu64 " for %s to next node %u "
         "with diff of %u entries.",
         cmd2->getMsgId(),
@@ -1204,7 +1206,8 @@ MergeHandler::handleGetBucketDiff(api::GetBucketDiffCommand& cmd,
         LOG(error, "Diffing %s found suspect entries.",
             bucket.toString().c_str());
     }
-    _env._metrics.mergeMetadataReadLatency.addValue(startTime);
+    _env._metrics.mergeMetadataReadLatency.addValue(
+            startTime.getElapsedTimeAsDouble());
 
     // If last node in merge chain, we can send reply straight away
     if (index + 1u >= cmd.getNodes().size()) {
@@ -1343,7 +1346,8 @@ MergeHandler::handleGetBucketDiffReply(api::GetBucketDiffReply& reply,
                     // We have sent something on, and shouldn't reply now.
                     clearState = false;
                 } else {
-                    _env._metrics.mergeLatencyTotal.addValue(s.startTime);
+                    _env._metrics.mergeLatencyTotal.addValue(
+                            s.startTime.getElapsedTimeAsDouble());
                 }
             }
         } else {
@@ -1397,7 +1401,8 @@ MergeHandler::handleApplyBucketDiff(api::ApplyBucketDiffCommand& cmd,
        framework::MilliSecTimer startTime(_env._component.getClock());
         fetchLocalData(bucket, cmd.getLoadType(), cmd.getDiff(), index,
                        context);
-        _env._metrics.mergeDataReadLatency.addValue(startTime);
+        _env._metrics.mergeDataReadLatency.addValue(
+                startTime.getElapsedTimeAsDouble());
     } else {
         LOG(spam, "Merge(%s): Moving %" PRIu64 " entries, didn't need "
                   "local data on node %u (%u).",
@@ -1410,7 +1415,8 @@ MergeHandler::handleApplyBucketDiff(api::ApplyBucketDiffCommand& cmd,
        framework::MilliSecTimer startTime(_env._component.getClock());
         api::BucketInfo info(applyDiffLocally(bucket, cmd.getLoadType(),
                                               cmd.getDiff(), index, context));
-        _env._metrics.mergeDataWriteLatency.addValue(startTime);
+        _env._metrics.mergeDataWriteLatency.addValue(
+                startTime.getElapsedTimeAsDouble());
     } else {
         LOG(spam, "Merge(%s): Didn't need fetched data on node %u (%u).",
             bucket.toString().c_str(), _env._nodeIndex, index);
@@ -1512,7 +1518,7 @@ MergeHandler::handleApplyBucketDiffReply(api::ApplyBucketDiffReply& reply,
                 fetchLocalData(bucket, reply.getLoadType(), diff, index,
                                s.context);
                 _env._metrics.mergeDataReadLatency.addValue(
-                        startTime);
+                        startTime.getElapsedTimeAsDouble());
             }
             if (applyDiffHasLocallyNeededData(diff, index)) {
                 framework::MilliSecTimer startTime(_env._component.getClock());
@@ -1520,7 +1526,7 @@ MergeHandler::handleApplyBucketDiffReply(api::ApplyBucketDiffReply& reply,
                         applyDiffLocally(bucket, reply.getLoadType(), diff,
                                          index, s.context));
                 _env._metrics.mergeDataWriteLatency.addValue(
-                        startTime);
+                        startTime.getElapsedTimeAsDouble());
             } else {
                 LOG(spam, "Merge(%s): Didn't need fetched data on node %u (%u)",
                     bucket.toString().c_str(),
@@ -1566,7 +1572,8 @@ MergeHandler::handleApplyBucketDiffReply(api::ApplyBucketDiffReply& reply,
                     // We have sent something on and shouldn't reply now.
                     clearState = false;
                 } else {
-                    _env._metrics.mergeLatencyTotal.addValue(s.startTime);
+                    _env._metrics.mergeLatencyTotal.addValue(
+                            s.startTime.getElapsedTimeAsDouble());
                 }
             }
         } else {
diff --git a/storage/src/vespa/storage/persistence/persistenceutil.cpp b/storage/src/vespa/storage/persistence/persistenceutil.cpp
index 5c023707937..72e68d47182 100644
--- a/storage/src/vespa/storage/persistence/persistenceutil.cpp
+++ b/storage/src/vespa/storage/persistence/persistenceutil.cpp
@@ -32,7 +32,7 @@ MessageTracker::MessageTracker(FileStorThreadMetrics::Op& metric,
 MessageTracker::~MessageTracker()
 {
     if (_reply.get() && _reply->getResult().success()) {
-        _metric.latency.addValue(_timer);
+        _metric.latency.addValue(_timer.getElapsedTimeAsDouble());
     }
 }
 
diff --git a/storage/src/vespa/storage/storageserver/communicationmanager.cpp b/storage/src/vespa/storage/storageserver/communicationmanager.cpp
index a2eb5bf5edd..0c02a4f6f69 100644
--- a/storage/src/vespa/storage/storageserver/communicationmanager.cpp
+++ b/storage/src/vespa/storage/storageserver/communicationmanager.cpp
@@ -462,13 +462,14 @@ CommunicationManager::process(const std::shared_ptr<api::StorageMessage>& msg)
         }
 
         LOG(spam, "Done processing: %s", msg->toString().c_str());
-        _metrics.messageProcessTime[msg->getLoadType()].addValue(startTime);
+        _metrics.messageProcessTime[msg->getLoadType()].addValue(
+                startTime.getElapsedTimeAsDouble());
     } catch (std::exception& e) {
         LOGBP(error, "When running command %s, caught exception %s. "
                      "Discarding message",
               msg->toString().c_str(), e.what());
         _metrics.exceptionMessageProcessTime[msg->getLoadType()].addValue(
-                startTime);
+                startTime.getElapsedTimeAsDouble());
     } catch (...) {
         LOG(fatal, "Caught fatal exception in communication manager");
         throw;
@@ -642,7 +643,7 @@ CommunicationManager::sendCommand(
     default:
         return false;
     }
-    _metrics.sendCommandLatency.addValue(startTime);
+    _metrics.sendCommandLatency.addValue(startTime.getElapsedTimeAsDouble());
     return true;
 }
 
@@ -797,7 +798,7 @@ CommunicationManager::sendReply(
     } else {
         sendMessageBusReply(*context, reply);
     }
-    _metrics.sendReplyLatency.addValue(startTime);
+    _metrics.sendReplyLatency.addValue(startTime.getElapsedTimeAsDouble());
     return true;
 }
 
diff --git a/storage/src/vespa/storage/storageserver/communicationmanagermetrics.h b/storage/src/vespa/storage/storageserver/communicationmanagermetrics.h
index 03f934c606a..4b580f79904 100644
--- a/storage/src/vespa/storage/storageserver/communicationmanagermetrics.h
+++ b/storage/src/vespa/storage/storageserver/communicationmanagermetrics.h
@@ -15,23 +15,23 @@ namespace storage {
 
 struct CommunicationManagerMetrics : public metrics::MetricSet {
     metrics::LongAverageMetric queueSize;
-    metrics::LoadMetric<metrics::LongAverageMetric> messageProcessTime;
-    metrics::LoadMetric<metrics::LongAverageMetric> exceptionMessageProcessTime;
+    metrics::LoadMetric<metrics::DoubleAverageMetric> messageProcessTime;
+    metrics::LoadMetric<metrics::DoubleAverageMetric> exceptionMessageProcessTime;
     metrics::LongCountMetric failedDueToTooLittleMemory;
     metrics::LongCountMetric convertToStorageAPIFailures;
-    metrics::LongAverageMetric sendCommandLatency;
-    metrics::LongAverageMetric sendReplyLatency;
+    metrics::DoubleAverageMetric sendCommandLatency;
+    metrics::DoubleAverageMetric sendReplyLatency;
 
     CommunicationManagerMetrics(const metrics::LoadTypeSet& loadTypes,
                                 metrics::MetricSet* owner = 0)
         : metrics::MetricSet("communication", "",
                 "Metrics for the communication manager", owner),
           queueSize("messagequeue", "", "Size of input message queue.", this),
-          messageProcessTime(loadTypes, metrics::LongAverageMetric(
+          messageProcessTime(loadTypes, metrics::DoubleAverageMetric(
                   "messageprocesstime", "",
                   "Time transport thread uses to process a single message"),
                   this),
-          exceptionMessageProcessTime(loadTypes, metrics::LongAverageMetric(
+          exceptionMessageProcessTime(loadTypes, metrics::DoubleAverageMetric(
                   "exceptionmessageprocesstime", "",
                   "Time transport thread uses to process a single message "
                   "that fails with an exception thrown into communication "
diff --git a/storage/src/vespa/storage/visiting/visitor.cpp b/storage/src/vespa/storage/visiting/visitor.cpp
index fc32b99e5cb..7270752e7a9 100644
--- a/storage/src/vespa/storage/visiting/visitor.cpp
+++ b/storage/src/vespa/storage/visiting/visitor.cpp
@@ -874,7 +874,7 @@ Visitor::onGetIterReply(const std::shared_ptr<GetIterReply>& reply,
                                 reply->getEntries(),
                                 *_hitCounter);
                 metrics.averageProcessingTime[reply->getLoadType()]
-                    .addValue(processingTimer);
+                    .addValue(processingTimer.getElapsedTimeAsDouble());
 
                 MBUS_TRACE(reply->getTrace(), 5, "Done processing data block in visitor plugin");
 
diff --git a/storage/src/vespa/storage/visiting/visitormetrics.h b/storage/src/vespa/storage/visiting/visitormetrics.h
index 100c2e70896..8e0971ff1ab 100644
--- a/storage/src/vespa/storage/visiting/visitormetrics.h
+++ b/storage/src/vespa/storage/visiting/visitormetrics.h
@@ -19,9 +19,9 @@ struct VisitorMetrics : public metrics::MetricSet
     metrics::LongAverageMetric queueSize;
     metrics::LongCountMetric queueSkips;
     metrics::LongCountMetric queueFull;
-    metrics::LongAverageMetric queueWaitTime;
-    metrics::LongAverageMetric queueTimeoutWaitTime;
-    metrics::LongAverageMetric queueEvictedWaitTime;
+    metrics::DoubleAverageMetric queueWaitTime;
+    metrics::DoubleAverageMetric queueTimeoutWaitTime;
+    metrics::DoubleAverageMetric queueEvictedWaitTime;
     std::vector<std::shared_ptr<VisitorThreadMetrics> > threads;
     metrics::SumMetric<MetricSet> sum;