From 1a4a4b3e5e0fb66549f34c53fccceccce0cf04a4 Mon Sep 17 00:00:00 2001 From: Sven Breuner Date: Sun, 4 Dec 2022 22:05:35 +0100 Subject: [PATCH] service: add new option "--svcelapsed" This option shows service instances ordered by completion time of their slowest thread to make it easier to see if some services are always slower/faster than others. Also bump version number. --- CHANGELOG.md | 8 ++++++++ Makefile | 2 +- source/ProgArgs.cpp | 5 +++++ source/ProgArgs.h | 5 ++++- source/Statistics.cpp | 41 ++++++++++++++++++++++++++++++++++++++++- 5 files changed, 58 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0077338..bb8ad0a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,13 @@ # Changelog of elbencho +## v2.2.5 (Dec 04, 2022) + +### New Features & Enhancements +* New option "--svcelapsed" shows service instances ordered by completion time of their slowest thread to make it easier to see if some services are always slower/faster than others. + +### Contributors +* Thanks to Samuel Fulcomer for helpful comments and suggestions. + ## v2.2.3 (Sep 18, 2022) ### New Features & Enhancements diff --git a/Makefile b/Makefile index 3ad06de..2ff1c1e 100644 --- a/Makefile +++ b/Makefile @@ -5,7 +5,7 @@ EXE_NAME ?= elbencho EXE_VER_MAJOR ?= 2 EXE_VER_MINOR ?= 2 -EXE_VER_PATCHLEVEL ?= 3 +EXE_VER_PATCHLEVEL ?= 5 EXE_VERSION ?= $(EXE_VER_MAJOR).$(EXE_VER_MINOR)-$(EXE_VER_PATCHLEVEL) EXE ?= $(BIN_PATH)/$(EXE_NAME) EXE_UNSTRIPPED ?= $(EXE)-unstripped diff --git a/source/ProgArgs.cpp b/source/ProgArgs.cpp index 07fd45c..417093d 100644 --- a/source/ProgArgs.cpp +++ b/source/ProgArgs.cpp @@ -418,6 +418,8 @@ void ProgArgs::defineAllowedArgs() "Start time of first benchmark in UTC seconds since the epoch. Intended to synchronize " "start of benchmarks on different hosts, assuming they use synchronized clocks. " "(Hint: Try 'date +%s' to get seconds since the epoch.)") +/*sv*/ (ARG_SHOWSVCELAPSED_LONG, bpo::bool_switch(&this->showServicesElapsed), + "Show elapsed time to completion of each service instance ordered by slowest thread.") /*sv*/ (ARG_SVCUPDATEINTERVAL_LONG, bpo::value(&this->svcUpdateIntervalMS), "Update retrieval interval for service hosts in milliseconds. (Default: 500)") /*sy*/ (ARG_SYNCPHASE_LONG, bpo::bool_switch(&this->runSyncPhase), @@ -509,6 +511,7 @@ void ProgArgs::defineDefaults() this->rankOffset = 0; this->logLevel = Log_NORMAL; this->showAllElapsed = false; + this->showServicesElapsed = false; this->liveStatsSleepMS = 2000; this->useRandomOffsets = false; this->useRandomAligned = false; @@ -2288,6 +2291,8 @@ void ProgArgs::printHelpDistributed() (ARG_NOSVCPATHSHARE_LONG, bpo::bool_switch(&this->noSharedServicePath), "Benchmark paths are not shared between service hosts. Thus, each service host will" "work on the full given dataset instead of its own fraction of the data set.") + (ARG_SHOWSVCELAPSED_LONG, bpo::bool_switch(&this->showServicesElapsed), + "Show elapsed time to completion of each service instance ordered by slowest thread.") (ARG_INTERRUPT_LONG, bpo::bool_switch(&this->interruptServices), "Interrupt current benchmark phase on given service mode hosts.") (ARG_FOREGROUNDSERVICE_LONG, bpo::bool_switch(&this->runServiceInForeground), diff --git a/source/ProgArgs.h b/source/ProgArgs.h index f898a11..4c3e528 100644 --- a/source/ProgArgs.h +++ b/source/ProgArgs.h @@ -70,6 +70,7 @@ namespace bpt = boost::property_tree; #define ARG_NUMAZONES_LONG "zones" #define ARG_CPUCORES_LONG "cores" #define ARG_SHOWALLELAPSED_LONG "allelapsed" +#define ARG_SHOWSVCELAPSED_LONG "svcelapsed" #define ARG_RANDOMOFFSETS_LONG "rand" #define ARG_RANDOMALIGN_LONG "randalign" #define ARG_RANDOMAMOUNT_LONG "randamount" @@ -245,7 +246,8 @@ class ProgArgs IntVec numaZonesVec; // list from numaZoneStr broken down into individual elements std::string cpuCoresStr; // comma-separted cpu cores that this process may run on IntVec cpuCoresVec; // list from cpuCoresStr broken down into individual elements - bool showAllElapsed; // print elapsed time of each I/O worker + bool showAllElapsed; // print elapsed time of each I/O worker thread + bool showServicesElapsed; // print elapsed time of each service by slowest thread size_t liveStatsSleepMS; // interval between live stats console/csv updates bool useRandomOffsets; // use random offsets for file reads/writes bool useRandomAligned; // use block-aligned random offsets (when randomOffsets is used) @@ -412,6 +414,7 @@ class ProgArgs std::string getCPUCoresStr() const { return cpuCoresStr; } const IntVec& getCPUCoresVec() const { return cpuCoresVec; } bool getShowAllElapsed() const { return showAllElapsed; } + bool getShowServicesElapsed() const { return showServicesElapsed; } size_t getLiveStatsSleepMS() const { return liveStatsSleepMS; } bool getUseRandomOffsets() const { return useRandomOffsets; } bool getUseRandomAligned() const { return useRandomAligned; } diff --git a/source/Statistics.cpp b/source/Statistics.cpp index 65123dc..1dc523c 100644 --- a/source/Statistics.cpp +++ b/source/Statistics.cpp @@ -1418,7 +1418,6 @@ void Statistics::printPhaseResultsToStream(const PhaseResults& phaseResults, // print individual elapsed time results for each worker if(progArgs.getShowAllElapsed() ) { - // individual results header (note: keep format in sync with general table format string) outStream << boost::format(Statistics::phaseResultsLeftFormatStr) % "" % "Time ms each" @@ -1436,6 +1435,46 @@ void Statistics::printPhaseResultsToStream(const PhaseResults& phaseResults, outStream << "]" << std::endl; } + // print hosts sorted from fastest to slowest (if this was a distributed run) + if(progArgs.getShowServicesElapsed() && !progArgs.getHostsVec().empty() ) + { + outStream << boost::format(Statistics::phaseResultsLeftFormatStr) + % "" + % "Service compl. ms" + % ":"; + + outStream << "[ "; + + typedef std::multimap CompletionTimeMultiMap; + typedef CompletionTimeMultiMap::value_type CompletionTimeMultiMapVal; + CompletionTimeMultiMap completionTimeMap; // key is time ms, val is svc name + + // build map by slowest finisher of each service instance + for(Worker* worker : workerVec) + { + RemoteWorker* remoteWorker = static_cast(worker); + uint64_t slowestThreadUSec = 0; + + // find slowest thread of this service instance + for(uint64_t elapsedUSec : worker->getElapsedUSecVec() ) + { + if(elapsedUSec > slowestThreadUSec) + slowestThreadUSec = elapsedUSec; + } + + completionTimeMap.insert( + CompletionTimeMultiMapVal(slowestThreadUSec/1000, remoteWorker->getHost() ) ); + } + + // services are now ordered by completion time of their slowest thread through the map + + // print ordered list of services ascending by slowest thread completion time + for(const CompletionTimeMultiMapVal& mapVal : completionTimeMap) + outStream << mapVal.second << "=" << mapVal.first << " "; + + outStream << "]" << std::endl; + } + // entries & iops latency results printPhaseResultsLatencyToStream(phaseResults.entriesLatHisto, entryTypeUpperCase + (isRWMixThreadsPhase ? " wr" : ""), outStream);