diff options
17 files changed, 106 insertions, 90 deletions
diff --git a/memfilepersistence/src/tests/spi/memfiletestutils.h b/memfilepersistence/src/tests/spi/memfiletestutils.h index d2bf5a9c635..d6bdbc3ff96 100644 --- a/memfilepersistence/src/tests/spi/memfiletestutils.h +++ b/memfilepersistence/src/tests/spi/memfiletestutils.h @@ -32,21 +32,25 @@ public: framework::MicroSecTime _absoluteTime; - FakeClock() {}; + FakeClock() {} virtual void addSecondsToTime(uint32_t nr) { _absoluteTime += framework::MicroSecTime(nr * uint64_t(1000000)); } - virtual framework::MicroSecTime getTimeInMicros() const { + framework::MicroSecTime getTimeInMicros() const override { return _absoluteTime; } - virtual framework::MilliSecTime getTimeInMillis() const { + framework::MilliSecTime getTimeInMillis() const override { return getTimeInMicros().getMillis(); } - virtual framework::SecondTime getTimeInSeconds() const { + framework::SecondTime getTimeInSeconds() const override { return getTimeInMicros().getSeconds(); } + framework::MonotonicTimePoint getMonotonicTime() const override { + return framework::MonotonicTimePoint(std::chrono::microseconds( + getTimeInMicros().getTime())); + } }; struct MemFileTestEnvironment { diff --git a/memfilepersistence/src/vespa/memfilepersistence/mapper/memfile_v1_serializer.cpp b/memfilepersistence/src/vespa/memfilepersistence/mapper/memfile_v1_serializer.cpp index 12f7219e2ca..2c683059fa5 100644 --- a/memfilepersistence/src/vespa/memfilepersistence/mapper/memfile_v1_serializer.cpp +++ b/memfilepersistence/src/vespa/memfilepersistence/mapper/memfile_v1_serializer.cpp @@ -137,7 +137,7 @@ MemFileV1Serializer::loadFile(MemFile& file, Environment& env, } assert(bytesRead == firstAlignedHeaderByte); } - metrics.tooLargeMetaReadLatency.addValue(timer); + metrics.tooLargeMetaReadLatency.addValue(timer.getElapsedTimeAsDouble()); } FileInfo::UP data(new FileInfo); @@ -314,25 +314,25 @@ MemFileV1Serializer::cacheLocations(MemFileIOInterface& io, buf.getSharedBuffer()->getUsedSize(), buf.getSharedBuffer()->getFreeSize()); - framework::MilliSecTime readStart(env._clock.getTimeInMillis()); + framework::MilliSecTimer readTimer(env._clock); SerializationMetrics& metrics(getMetrics().serialization); uint64_t total(read(cache.getFileHandle(), buf.getBuffer(), readLocations)); - metrics::LongAverageMetric& latency(part == HEADER ? metrics.headerReadLatency - : metrics.bodyReadLatency); + metrics::DoubleAverageMetric& latency( + part == HEADER ? metrics.headerReadLatency + : metrics.bodyReadLatency); metrics::LongAverageMetric& sz(part == HEADER ? metrics.headerReadSize : metrics.bodyReadSize); - framework::MilliSecTime readDone(env._clock.getTimeInMillis()); - latency.addValue((readDone - readStart).getTime()); + latency.addValue(readTimer.getElapsedTimeAsDouble()); sz.addValue(total); + framework::MilliSecTimer cacheUpdateTimer(env._clock); cacheLocationsForPart(cache, part, blockStartIndex, locations, readLocations, buf); - framework::MilliSecTime timeNow(env._clock.getTimeInMillis()); metrics.cacheUpdateAndImplicitVerifyLatency.addValue( - (timeNow - readDone).getTime()); + cacheUpdateTimer.getElapsedTimeAsDouble()); } uint64_t @@ -403,7 +403,7 @@ MemFileV1Serializer::writeMetaData(BufferedFileWriter& writer, MemFileV1Serializer::FlushResult MemFileV1Serializer::flushUpdatesToFile(MemFile& file, Environment& env) { - framework::MilliSecTime startTime(env._clock.getTimeInMillis()); + framework::MilliSecTimer totalWriteTimer(env._clock); MemFilePersistenceThreadMetrics& metrics(getMetrics()); SerializationWriteMetrics& writeMetrics(metrics.serialization.partialWrite); SimpleMemFileIOBuffer& ioBuf( @@ -556,9 +556,9 @@ MemFileV1Serializer::flushUpdatesToFile(MemFile& file, Environment& env) // we only write the raw data to disk. Buffer buffer(1024 * 1024); BufferedFileWriter writer(ioBuf.getFileHandle(), buffer, buffer.getSize()); - framework::MilliSecTime locationWriteTime(env._clock.getTimeInMillis()); for (uint32_t partId = 0; partId < 2; ++partId) { + framework::MilliSecTimer writeTimer(env._clock); DocumentPart part(static_cast<DocumentPart>(partId)); LocationMap& locations(part == HEADER ? headersToWrite : bodiesToWrite); @@ -609,16 +609,17 @@ MemFileV1Serializer::flushUpdatesToFile(MemFile& file, Environment& env) assert(part == BODY || pos <= data.getBlockIndex(BODY)); writer.writeGarbage(pos - writer.getFilePosition()); - framework::MilliSecTime timeNow(env._clock.getTimeInMillis()); - metrics::LongAverageMetric& latency(part == HEADER ? writeMetrics.headerLatency - : writeMetrics.bodyLatency); - metrics::LongAverageMetric& sz(part == HEADER ? writeMetrics.headerSize - : writeMetrics.bodySize); - latency.addValue((timeNow - locationWriteTime).getTime()); + metrics::DoubleAverageMetric& latency( + part == HEADER ? writeMetrics.headerLatency + : writeMetrics.bodyLatency); + metrics::LongAverageMetric& sz( + part == HEADER ? writeMetrics.headerSize + : writeMetrics.bodySize); + latency.addValue(writeTimer.getElapsedTimeAsDouble()); sz.addValue(bytesToWrite[part]); - locationWriteTime = timeNow; } + framework::MilliSecTimer metaWriteTimer(env._clock); // Write metadata back to file writer.setFilePosition(0); writeMetaData(writer, file); @@ -626,10 +627,9 @@ MemFileV1Serializer::flushUpdatesToFile(MemFile& file, Environment& env) writer.flush(); MapperSlotOperation::clearFlag(file, SLOTS_ALTERED); - framework::MilliSecTime finishTime(env._clock.getTimeInMillis()); - writeMetrics.metaLatency.addValue((finishTime - locationWriteTime).getTime()); + writeMetrics.metaLatency.addValue(metaWriteTimer.getElapsedTimeAsDouble()); + writeMetrics.totalLatency.addValue(totalWriteTimer.getElapsedTimeAsDouble()); writeMetrics.metaSize.addValue(writer.getFilePosition()); - writeMetrics.totalLatency.addValue((finishTime - startTime).getTime()); return FlushResult::ChangesWritten; } @@ -832,11 +832,13 @@ MemFileV1Serializer::writeAndUpdateLocations( SerializationWriteMetrics& writeMetrics( getMetrics().serialization.fullWrite); - metrics::LongAverageMetric& latency(part == HEADER ? writeMetrics.headerLatency - : writeMetrics.bodyLatency); - metrics::LongAverageMetric& sz(part == HEADER ? writeMetrics.headerSize - : writeMetrics.bodySize); - latency.addValue(timer); + metrics::DoubleAverageMetric& latency( + part == HEADER ? writeMetrics.headerLatency + : writeMetrics.bodyLatency); + metrics::LongAverageMetric& sz( + part == HEADER ? writeMetrics.headerSize + : writeMetrics.bodySize); + latency.addValue(timer.getElapsedTimeAsDouble()); sz.addValue(index); // Equal to written size. return index; @@ -845,7 +847,7 @@ MemFileV1Serializer::writeAndUpdateLocations( void MemFileV1Serializer::rewriteFile(MemFile& file, Environment& env) { - framework::MilliSecTime startTime(env._clock.getTimeInMillis()); + framework::MilliSecTimer totalWriteTimer(env._clock); SerializationWriteMetrics& writeMetrics( getMetrics().serialization.fullWrite); file.ensureHeaderAndBodyBlocksCached(); @@ -933,7 +935,7 @@ MemFileV1Serializer::rewriteFile(MemFile& file, Environment& env) writer.writeGarbage(data->_bodyBlockSize - bodyIndex); } - framework::MilliSecTime timeBeforeMetaWrite(env._clock.getTimeInMillis()); + framework::MilliSecTimer metaWriteTimer(env._clock); // Update meta entries std::vector<MetaSlot> writeSlots(header._metaDataListSize); @@ -1004,10 +1006,9 @@ MemFileV1Serializer::rewriteFile(MemFile& file, Environment& env) } MapperSlotOperation::clearFlag(file, SLOTS_ALTERED); - framework::MilliSecTime timeAfterMetaWrite(env._clock.getTimeInMillis()); - writeMetrics.metaLatency.addValue((timeAfterMetaWrite - timeBeforeMetaWrite).getTime()); + writeMetrics.metaLatency.addValue(metaWriteTimer.getElapsedTimeAsDouble()); + writeMetrics.totalLatency.addValue(totalWriteTimer.getElapsedTimeAsDouble()); writeMetrics.metaSize.addValue(sizeof(MetaSlot) * header._metaDataListSize); - writeMetrics.totalLatency.addValue((timeAfterMetaWrite - startTime).getTime()); } bool @@ -1021,7 +1022,7 @@ MemFileV1Serializer::verify(MemFile& file, Environment& env, bool ok(verifier.verify(file, env, reportStream, repairErrors, fileVerifyFlags)); - metrics.verifyLatency.addValue(timer); + metrics.verifyLatency.addValue(timer.getElapsedTimeAsDouble()); return ok; } diff --git a/memfilepersistence/src/vespa/memfilepersistence/mapper/memfilemapper.cpp b/memfilepersistence/src/vespa/memfilepersistence/mapper/memfilemapper.cpp index 9d9360a3d3a..686ff05cf0e 100644 --- a/memfilepersistence/src/vespa/memfilepersistence/mapper/memfilemapper.cpp +++ b/memfilepersistence/src/vespa/memfilepersistence/mapper/memfilemapper.cpp @@ -156,7 +156,7 @@ MemFileMapper::loadFileImpl(MemFile& file, Environment& env) throw CorruptMemFileException(err.str(), file.getFile(), VESPA_STRLOC); } SerializationMetrics& metrics(getMetrics().serialization); - metrics.initialMetaReadLatency.addValue(timer); + metrics.initialMetaReadLatency.addValue(timer.getElapsedTimeAsDouble()); file.setFlag(BUCKET_INFO_OUTDATED); @@ -172,7 +172,7 @@ MemFileMapper::loadFileImpl(MemFile& file, Environment& env) } serializer->second->loadFile(file, env, buffer, readBytes); - metrics.totalLoadFileLatency.addValue(timer); + metrics.totalLoadFileLatency.addValue(timer.getElapsedTimeAsDouble()); } void @@ -292,7 +292,8 @@ MemFileMapper::deleteFile(const MemFile& constFile, Environment& env) PartitionMonitor& partitionMonitor( *constFile.getFile().getDirectory().getPartition().getMonitor()); partitionMonitor.removingData(fileSize); - getMetrics().serialization.deleteFileLatency.addValue(timer); + getMetrics().serialization.deleteFileLatency.addValue( + timer.getElapsedTimeAsDouble()); } void diff --git a/memfilepersistence/src/vespa/memfilepersistence/mapper/serializationmetrics.h b/memfilepersistence/src/vespa/memfilepersistence/mapper/serializationmetrics.h index ac55b546b9e..7a53bf31c7b 100644 --- a/memfilepersistence/src/vespa/memfilepersistence/mapper/serializationmetrics.h +++ b/memfilepersistence/src/vespa/memfilepersistence/mapper/serializationmetrics.h @@ -9,13 +9,13 @@ namespace memfile { class SerializationWriteMetrics : public metrics::MetricSet { public: - metrics::LongAverageMetric headerLatency; + metrics::DoubleAverageMetric headerLatency; metrics::LongAverageMetric headerSize; - metrics::LongAverageMetric bodyLatency; + metrics::DoubleAverageMetric bodyLatency; metrics::LongAverageMetric bodySize; - metrics::LongAverageMetric metaLatency; + metrics::DoubleAverageMetric metaLatency; metrics::LongAverageMetric metaSize; - metrics::LongAverageMetric totalLatency; + metrics::DoubleAverageMetric totalLatency; SerializationWriteMetrics(const std::string& name, MetricSet& owner); ~SerializationWriteMetrics(); @@ -24,16 +24,16 @@ public: class SerializationMetrics : public metrics::MetricSet { public: - metrics::LongAverageMetric initialMetaReadLatency; - metrics::LongAverageMetric tooLargeMetaReadLatency; - metrics::LongAverageMetric totalLoadFileLatency; - metrics::LongAverageMetric verifyLatency; - metrics::LongAverageMetric deleteFileLatency; - metrics::LongAverageMetric headerReadLatency; + metrics::DoubleAverageMetric initialMetaReadLatency; + metrics::DoubleAverageMetric tooLargeMetaReadLatency; + metrics::DoubleAverageMetric totalLoadFileLatency; + metrics::DoubleAverageMetric verifyLatency; + metrics::DoubleAverageMetric deleteFileLatency; + metrics::DoubleAverageMetric headerReadLatency; metrics::LongAverageMetric headerReadSize; - metrics::LongAverageMetric bodyReadLatency; + metrics::DoubleAverageMetric bodyReadLatency; metrics::LongAverageMetric bodyReadSize; - metrics::LongAverageMetric cacheUpdateAndImplicitVerifyLatency; + metrics::DoubleAverageMetric cacheUpdateAndImplicitVerifyLatency; metrics::LongCountMetric fullRewritesDueToDownsizingFile; metrics::LongCountMetric fullRewritesDueToTooSmallFile; SerializationWriteMetrics partialWrite; diff --git a/persistence/src/vespa/persistence/spi/metricpersistenceprovider.cpp b/persistence/src/vespa/persistence/spi/metricpersistenceprovider.cpp index 0395b52df81..ae70872b5b0 100644 --- a/persistence/src/vespa/persistence/spi/metricpersistenceprovider.cpp +++ b/persistence/src/vespa/persistence/spi/metricpersistenceprovider.cpp @@ -25,7 +25,7 @@ namespace { typedef MetricPersistenceProvider Impl; } -using metrics::LongAverageMetric; +using metrics::DoubleAverageMetric; using std::make_unique; Impl::ResultMetrics::~ResultMetrics() { } @@ -34,12 +34,12 @@ Impl::ResultMetrics::ResultMetrics(const char* opName) : metrics::MetricSet(opName, "", ""), _metric(Result::ERROR_COUNT) { - _metric[Result::NONE] = make_unique<LongAverageMetric>("success", "", "", this); - _metric[Result::TRANSIENT_ERROR] = make_unique<LongAverageMetric>("transient_error", "", "", this); - _metric[Result::PERMANENT_ERROR] = make_unique<LongAverageMetric>("permanent_error", "", "", this); - _metric[Result::TIMESTAMP_EXISTS] = make_unique<LongAverageMetric>("timestamp_exists", "", "", this); - _metric[Result::FATAL_ERROR] = make_unique<LongAverageMetric>("fatal_error", "", "", this); - _metric[Result::RESOURCE_EXHAUSTED] = make_unique<LongAverageMetric>("resource_exhausted", "", "", this); + _metric[Result::NONE] = make_unique<DoubleAverageMetric>("success", "", "", this); + _metric[Result::TRANSIENT_ERROR] = make_unique<DoubleAverageMetric>("transient_error", "", "", this); + _metric[Result::PERMANENT_ERROR] = make_unique<DoubleAverageMetric>("permanent_error", "", "", this); + _metric[Result::TIMESTAMP_EXISTS] = make_unique<DoubleAverageMetric>("timestamp_exists", "", "", this); + _metric[Result::FATAL_ERROR] = make_unique<DoubleAverageMetric>("fatal_error", "", "", this); + _metric[Result::RESOURCE_EXHAUSTED] = make_unique<DoubleAverageMetric>("resource_exhausted", "", "", this); // Assert that the above initialized all entries in vector for (size_t i=0; i<_metric.size(); ++i) assert(_metric[i].get()); } diff --git a/persistence/src/vespa/persistence/spi/metricpersistenceprovider.h b/persistence/src/vespa/persistence/spi/metricpersistenceprovider.h index 1f9884c03c8..65246140e03 100644 --- a/persistence/src/vespa/persistence/spi/metricpersistenceprovider.h +++ b/persistence/src/vespa/persistence/spi/metricpersistenceprovider.h @@ -15,7 +15,7 @@ class MetricPersistenceProvider : public PersistenceProvider, public metrics::MetricSet { struct ResultMetrics : public metrics::MetricSet { - std::vector<std::unique_ptr<metrics::LongAverageMetric> > _metric; + std::vector<std::unique_ptr<metrics::DoubleAverageMetric> > _metric; ResultMetrics(const char* opName); ~ResultMetrics(); 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; |