Internal timers metrics #635

Added status variables:
* Backend_query_time_nsec
* Query_Processor_time_nsec

include/MySQL_Thread.h

@@ -165,6 +165,8 @@ class MySQL_Thread
 		unsigned long long queries_slow;
 		unsigned long long queries_backends_bytes_sent;
 		unsigned long long queries_backends_bytes_recv;
+		unsigned long long query_processor_time;
+		unsigned long long backend_query_time;
 		unsigned int active_transactions;
 	} status_variables;
 
@@ -350,6 +352,8 @@ class MySQL_Threads_Handler
 	unsigned long long get_queries_backends_bytes_recv();
 	unsigned long long get_queries_backends_bytes_sent();
 	unsigned int get_active_transations();
+	unsigned long long get_query_processor_time();
+	unsigned long long get_backend_query_time();
 	iface_info *MLM_find_iface_from_fd(int fd) {
 		return MLM->find_iface_from_fd(fd);
 	}

lib/MySQL_Session.cpp

@@ -740,8 +740,16 @@ __get_pkts_from_client:
 										RequestEnd(NULL);
 										break;
 									}
-
-									qpo=GloQPro->process_mysql_query(this,pkt.ptr,pkt.size,&CurrentQuery);
+									{
+										timespec begint;
+										clock_gettime(CLOCK_THREAD_CPUTIME_ID,&begint);
+										qpo=GloQPro->process_mysql_query(this,pkt.ptr,pkt.size,&CurrentQuery);
+										timespec endt;
+										clock_gettime(CLOCK_THREAD_CPUTIME_ID,&endt);
+										thread->status_variables.query_processor_time=thread->status_variables.query_processor_time +
+											(endt.tv_sec*1000000000+endt.tv_nsec) -
+											(begint.tv_sec*1000000000+begint.tv_nsec);
+									}
 									assert(qpo);	// GloQPro->process_mysql_query() should always return a qpo
 									rc_break=handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(&pkt);
 									if (rc_break==true) {
@@ -1076,7 +1084,14 @@ handler_again:
 						}
 					}
 				}
+				timespec begint;
+				clock_gettime(CLOCK_THREAD_CPUTIME_ID,&begint);
 				int rc=myconn->async_query(myds->revents, myds->mysql_real_query.QueryPtr,myds->mysql_real_query.QuerySize);
+				timespec endt;
+				clock_gettime(CLOCK_THREAD_CPUTIME_ID,&endt);
+				thread->status_variables.backend_query_time=thread->status_variables.backend_query_time +
+					(endt.tv_sec*1000000000+endt.tv_nsec) -
+					(begint.tv_sec*1000000000+begint.tv_nsec);
 
 //				if (myconn->async_state_machine==ASYNC_QUERY_END) {
 				if (rc==0) {
@@ -1970,6 +1985,8 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C
 		// the query was rewritten
 		l_free(pkt->size,pkt->ptr);	// free old pkt
 		// allocate new pkt
+		timespec begint;
+		clock_gettime(CLOCK_THREAD_CPUTIME_ID,&begint);
 		pkt->size=sizeof(mysql_hdr)+1+qpo->new_query->length();
 		pkt->ptr=l_alloc(pkt->size);
 		mysql_hdr hdr;
@@ -1982,6 +1999,11 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C
 		CurrentQuery.query_parser_free();
 		CurrentQuery.begin((unsigned char *)pkt->ptr,pkt->size,true);
 		delete qpo->new_query;
+		timespec endt;
+		clock_gettime(CLOCK_THREAD_CPUTIME_ID,&endt);
+		thread->status_variables.query_processor_time=thread->status_variables.query_processor_time +
+			(endt.tv_sec*1000000000+endt.tv_nsec) -
+			(begint.tv_sec*1000000000+begint.tv_nsec);
 	}
 
 	if (pkt->size > (unsigned int) mysql_thread___max_allowed_packet) {

lib/MySQL_Thread.cpp

@@ -2102,6 +2102,8 @@ MySQL_Thread::MySQL_Thread() {
 	status_variables.queries_slow=0;
 	status_variables.queries_backends_bytes_sent=0;
 	status_variables.queries_backends_bytes_recv=0;
+	status_variables.query_processor_time=0;
+	status_variables.backend_query_time=0;
 	status_variables.active_transactions=0;
 }
 
@@ -2230,6 +2232,18 @@ SQLite3_result * MySQL_Threads_Handler::SQL3_GlobalStatus() {
 		pta[1]=buf;
 		result->add_row(pta);
 	}
+	{	// Query Processor Time
+		pta[0]=(char *)"Query_Processor_time_nsec";
+		sprintf(buf,"%llu",get_query_processor_time());
+		pta[1]=buf;
+		result->add_row(pta);
+	}
+	{	// Backend query time
+		pta[0]=(char *)"Backend_query_time_nsec";
+		sprintf(buf,"%llu",get_backend_query_time());
+		pta[1]=buf;
+		result->add_row(pta);
+	}
 	{	// Queries autocommit
 		pta[0]=(char *)"Com_autocommit";
 		sprintf(buf,"%llu",MyHGM->status.autocommit_cnt);
@@ -2564,3 +2578,29 @@ unsigned int MySQL_Threads_Handler::get_active_transations() {
 	}
 	return q;
 }
+
+unsigned long long MySQL_Threads_Handler::get_query_processor_time() {
+	unsigned long long q=0;
+	unsigned int i;
+	for (i=0;i<num_threads;i++) {
+		if (mysql_threads) {
+			MySQL_Thread *thr=(MySQL_Thread *)mysql_threads[i].worker;
+			if (thr)
+				q+=__sync_fetch_and_add(&thr->status_variables.query_processor_time,0);
+		}
+	}
+	return q;
+}
+
+unsigned long long MySQL_Threads_Handler::get_backend_query_time() {
+	unsigned long long q=0;
+	unsigned int i;
+	for (i=0;i<num_threads;i++) {
+		if (mysql_threads) {
+			MySQL_Thread *thr=(MySQL_Thread *)mysql_threads[i].worker;
+			if (thr)
+				q+=__sync_fetch_and_add(&thr->status_variables.backend_query_time,0);
+		}
+	}
+	return q;
+}