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

@@ -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

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

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),

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; }

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<uint64_t, std::string> 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<RemoteWorker*>(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);