Maintain statistics for per-job-type times in various phases

JobScheduler.cpp

@@ -43,6 +43,7 @@ struct JobEntry {
 	uint64_t          queue_enter_time;   //when this job was queued
 	uint64_t          start_time;	      //when this job started running
 	uint64_t          stop_time;	      //when this job stopped running
+	uint64_t          finish_time;        //when the finish callback was called
 	uint64_t          exit_time;	      //when this job was finished, including finish-callback
 };
 
@@ -257,6 +258,8 @@ class JobScheduler_impl {
 	bool no_threads;
 	bool new_jobs_allowed;
 	
+	std::map<thread_type_t,JobTypeStatistics> job_statistics;
+	
 	bool submit(thread_type_t thread_type, JobEntry &e);
 public:
 	JobScheduler_impl(unsigned num_cpu_threads, unsigned num_io_threads, unsigned num_external_threads, job_done_notify_t job_done_notify)
@@ -311,6 +314,7 @@ public:
 	void cleanup_finished_jobs();
 	
 	std::vector<JobDigest> query_job_digests() const;
+	std::map<thread_type_t,JobTypeStatistics> query_job_statistics(bool clear);
 };
 
 
@@ -515,10 +519,17 @@ void JobScheduler_impl::cleanup_finished_jobs()
 	sl.unlock();
 	
 	for(auto e : es) {
+		e.first.finish_time = now_ms();
 		if(e.first.finish_callback)
 			e.first.finish_callback(e.first.state,e.second);
 		e.first.exit_time = now_ms();
-		//todo. register statistics
+		
+		JobTypeStatistics &s = job_statistics[e.first.thread_type];
+		s.job_count++;
+		s.queue_time += e.first.start_time - e.first.queue_enter_time;
+		s.running_time += e.first.stop_time - e.first.start_time;
+		s.done_time += e.first.finish_time - e.first.stop_time;
+		s.cleanup_time += e.first.exit_time - e.first.finish_time;
 	}
 }
 
@@ -558,6 +569,17 @@ std::vector<JobDigest> JobScheduler_impl::query_job_digests() const
 }
 
 
+std::map<thread_type_t,JobTypeStatistics> JobScheduler_impl::query_job_statistics(bool clear)
+{
+	if(clear) {
+		std::map<thread_type_t,JobTypeStatistics> tmp;
+		tmp.swap(job_statistics);
+		return tmp;
+	} else
+		return job_statistics;
+}
+
+
 
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -694,6 +716,15 @@ std::vector<JobDigest> JobScheduler::query_job_digests() const
 }
 
 
+std::map<thread_type_t,JobTypeStatistics> JobScheduler::query_job_statistics(bool clear)
+{
+	if(impl)
+		return impl->query_job_statistics(clear);
+	else
+		return std::map<thread_type_t,JobTypeStatistics>();
+}
+
+
 ////////////////////////////////////////////////////////////////////////////////
 // The global one-and-only scheduler
 

JobScheduler.h

@@ -3,6 +3,7 @@
 
 #include <inttypes.h>
 #include <vector>
+#include <map>
 
 
 class BigFile;
@@ -60,6 +61,16 @@ struct JobDigest {
 };
 
 
+//statistics for queue and execution time per thread type
+struct JobTypeStatistics {
+	uint64_t job_count;
+	uint64_t queue_time;            //time from enque to start, in nsecs
+	uint64_t running_time;          //time from start to stop, in nsecs
+	uint64_t done_time;             //time from stop to cleanup
+	uint64_t cleanup_time;          //time from in cleanup
+};
+
+
 class JobScheduler_impl;
 
 typedef void (*job_done_notify_t)();
@@ -102,6 +113,7 @@ public:
 	void cleanup_finished_jobs();
 	
 	std::vector<JobDigest> query_job_digests() const;
+	std::map<thread_type_t,JobTypeStatistics> query_job_statistics(bool clear=true);
 
 private:
 	JobScheduler_impl *impl;

PageThreads.cpp

@@ -135,6 +135,32 @@ bool sendPageThreads ( TcpSocket *s , HttpRequest *r ) {
 	
 	p.safePrintf("</table><br><br>");
 
+	//print timing / wait time / delay statistics per job type
+	p.safePrintf("<table %s>", TABLE_STYLE);
+	p.safePrintf("  <tr class=hdrow>\n");
+	p.safePrintf("    <td><b>Job type</b></td>\n");
+	p.safePrintf("    <td><b>Time in queue</b></td>\n");
+	p.safePrintf("    <td><b>Time executing</b></td>\n");
+	p.safePrintf("    <td><b>Time waiting for cleanup</b></td>\n");
+	p.safePrintf("    <td><b>Cleanup time</b></td>\n");
+	p.safePrintf("   </tr>\n");
+	for(const auto &js : g_jobScheduler.query_job_statistics(true)) {
+		p.safePrintf("  <tr bgcolor=#%s>\n",LIGHT_BLUE);
+		p.safePrintf("    <td>%s</td>", thread_type_name(js.first));
+		if(js.second.job_count!=0) {
+			p.safePrintf("    <td>%.3f</td>\n", js.second.queue_time/js.second.job_count/1000.0);
+			p.safePrintf("    <td>%.3f</td>\n", js.second.running_time/js.second.job_count/1000.0);
+			p.safePrintf("    <td>%.3f</td>\n", js.second.done_time/js.second.job_count/1000.0);
+			p.safePrintf("    <td>%.3f</td>\n", js.second.cleanup_time/js.second.job_count/1000.0);
+		} else {
+			p.safePrintf("    <td>-</td>\n");
+			p.safePrintf("    <td>-</td>\n");
+			p.safePrintf("    <td>-</td>\n");
+			p.safePrintf("    <td>-</td>\n");
+		}
+		p.safePrintf("   </tr>\n");
+	}
+
 	return g_httpServer.sendDynamicPage ( s , (char*) p.getBufStart() ,
 						p.length() );
 }