Update of /home/cvsd/slony1/slony1-engine/src/slon
In directory main.slony.info:/tmp/cvs-serv3690/src/slon

Modified Files:
	remote_worker.c 
Log Message:
Add in more detailed monitoring of numbers and timings of queries against
providers and subscribers, along with some documentation on how the log
output may be interpreted (at least, at the more technical level).



Index: remote_worker.c
===================================================================
RCS file: /home/cvsd/slony1/slony1-engine/src/slon/remote_worker.c,v
retrieving revision 1.174
retrieving revision 1.175
diff -C2 -d -r1.174 -r1.175
*** remote_worker.c	1 Aug 2008 20:18:17 -0000	1.174
--- remote_worker.c	1 Aug 2008 22:45:18 -0000	1.175
***************
*** 3777,3783 ****
  		start_monitored_event(&pm);
  		res1 = PQexec(local_dbconn, dstring_data(&query));
- 		slon_log(SLON_INFO, "about to monitor_subscriber_query - pulling big actionid list %d\n", provider);
  		monitor_subscriber_query(&pm);
  
  		if (PQresultStatus(res1) != PGRES_TUPLES_OK)
  		{
--- 3777,3784 ----
  		start_monitored_event(&pm);
  		res1 = PQexec(local_dbconn, dstring_data(&query));
  		monitor_subscriber_query(&pm);
  
+ 		slon_log(SLON_INFO, "about to monitor_subscriber_query - pulling big actionid list %d\n", provider);
+ 
  		if (PQresultStatus(res1) != PGRES_TUPLES_OK)
  		{
***************
*** 3834,3840 ****
--- 3835,3843 ----
  								rtcfg_namespace,
  								sub_set);
+ 
  			start_monitored_event(&pm);
  			res2 = PQexec(local_dbconn, dstring_data(&query));
  			monitor_subscriber_query(&pm);
+ 
  			if (PQresultStatus(res2) != PGRES_TUPLES_OK)
  			{
***************
*** 4008,4012 ****
--- 4011,4017 ----
  	(void) slon_mkquery(&query, "select last_value from %s.sl_log_status",
  						rtcfg_namespace);
+ 	start_monitored_event(&pm);
  	res1 = PQexec(local_dbconn, dstring_data(&query));
+ 	monitor_subscriber_query(&pm);
  
  	if (PQresultStatus(res1) != PGRES_TUPLES_OK)
***************
*** 4095,4102 ****
  					if (wgline->log.n_used > 0)
  					{
! 					  start_monitored_event(&pm);
  						res1 = PQexec(local_dbconn, dstring_data(&(wgline->log)));
  
- 					  monitor_subscriber_iud(&pm);
  						if (PQresultStatus(res1) == PGRES_EMPTY_QUERY)
  						{
--- 4100,4107 ----
  					if (wgline->log.n_used > 0)
  					{
! 						start_monitored_event(&pm);
  						res1 = PQexec(local_dbconn, dstring_data(&(wgline->log)));
+ 						monitor_subscriber_iud(&pm);
  
  						if (PQresultStatus(res1) == PGRES_EMPTY_QUERY)
  						{
***************
*** 4119,4122 ****
--- 4124,4128 ----
  					res1 = PQexec(local_dbconn, dstring_data(&(wgline->data)));
  					monitor_subscriber_iud(&pm);
+ 
  					if (PQresultStatus(res1) == PGRES_EMPTY_QUERY)
  					{
***************
*** 4299,4303 ****
  		start_monitored_event(&pm);
  		res1 = PQexec(provider->conn->dbconn, dstring_data(&query));
! 		monitor_subscriber_iud(&pm);
  		if (PQresultStatus(res1) != PGRES_TUPLES_OK)
  		{
--- 4305,4310 ----
  		start_monitored_event(&pm);
  		res1 = PQexec(provider->conn->dbconn, dstring_data(&query));
! 		monitor_provider_query(&pm);
! 
  		if (PQresultStatus(res1) != PGRES_TUPLES_OK)
  		{
***************
*** 4379,4383 ****
--- 4386,4394 ----
  		 */
  		slon_appendquery(&query, ") and ssy_seqno < '%s'; ", seqbuf);
+ 		
+ 		start_monitored_event(&pm);
  		res1 = PQexec(local_dbconn, dstring_data(&query));
+ 		monitor_subscriber_query (&pm);
+ 
  		if (PQresultStatus(res1) != PGRES_COMMAND_OK)
  		{
***************
*** 4419,4423 ****
  
   	slon_log(SLON_INFO, 
! 			 "remoteWorkerThread_%d: SYNC " INT64_FORMAT " Timing: " 
  			 " pqexec (s/count)" 
  			 "- provider %.3f/%d " 
--- 4430,4434 ----
  
   	slon_log(SLON_INFO, 
! 			 "remoteWorkerThread_%d: SYNC " INT64_FORMAT " sync_event timing: " 
  			 " pqexec (s/count)" 
  			 "- provider %.3f/%d " 
***************
*** 4470,4475 ****
  	PerfMon pm;
  
- 	init_perfmon(&pm);
- 
  	dstring_init(&query);
  	dstring_init(&query2);
--- 4481,4484 ----
***************
*** 4513,4522 ****
--- 4522,4536 ----
  		do
  		{
+ 			init_perfmon(&pm);
  			/*
  			 * Start a transaction
  			 */
+ 
  			(void) slon_mkquery(&query, "start transaction; "
  								"set enable_seqscan = off; "
  								"set enable_indexscan = on; ");
+ 
+ 			start_monitored_event(&pm);
+ 
  			if (query_execute(node, dbconn, &query) < 0)
  			{
***************
*** 4524,4527 ****
--- 4538,4542 ----
  				break;
  			}
+ 			monitor_subscriber_query (&pm);
  
  			/*
***************
*** 4530,4534 ****
--- 4545,4553 ----
  			(void) slon_mkquery(&query, "select last_value from %s.sl_log_status",
  								rtcfg_namespace);
+ 
+ 			start_monitored_event(&pm);
  			res3 = PQexec(dbconn, dstring_data(&query));
+ 			monitor_provider_query(&pm);
+ 
  			rc = PQresultStatus(res3);
  			if (rc != PGRES_TUPLES_OK)
***************
*** 4639,4642 ****
--- 4658,4662 ----
  			res = NULL;
  
+ 			start_monitored_event(&pm);
  			if (query_execute(node, dbconn, &query) < 0)
  			{
***************
*** 4644,4647 ****
--- 4664,4668 ----
  				break;
  			}
+ 			monitor_provider_query(&pm);
  
  			(void) slon_mkquery(&query, "fetch %d from LOG; ",
***************
*** 4775,4779 ****
--- 4796,4803 ----
  						PQclear(res);
  
+ 					start_monitored_event(&pm);
  					res = PQexec(dbconn, dstring_data(&query));
+ 					monitor_provider_query(&pm);
+ 
  					if (PQresultStatus(res) != PGRES_TUPLES_OK)
  					{
***************
*** 4840,4844 ****
  					if (log_cmdsize >= sync_max_rowsize)
  					{
- 						start_monitored_event(&pm);
  						(void) slon_mkquery(&query2,
  											"select log_cmddata "
--- 4864,4867 ----
***************
*** 4857,4862 ****
--- 4880,4887 ----
  											rtcfg_namespace,
  										log_origin, log_txid, log_actionseq);
+ 						start_monitored_event(&pm);
  						res2 = PQexec(dbconn, dstring_data(&query2));
  						monitor_largetuples(&pm);
+ 
  						if (PQresultStatus(res2) != PGRES_TUPLES_OK)
  						{
***************
*** 5044,5052 ****
  				 node->no_id, provider->no_id, pm.num_inserts, pm.num_updates, pm.num_deletes);
  
!  	slon_log(SLON_INFO, 
! 			 "remoteWorkerThread_%d: sync_helper timing: " 
! 			 " large tuples %.3f/%d\n", 
! 			 node->no_id, 
! 			 pm.large_tuples_t, pm.large_tuples_c);
  
  		/*
--- 5069,5086 ----
  				 node->no_id, provider->no_id, pm.num_inserts, pm.num_updates, pm.num_deletes);
  
! 		slon_log(SLON_INFO, 
! 				 "remoteWorkerThread_%d: sync_helper timing: " 
! 				 " pqexec (s/count)" 
! 				 "- provider %.3f/%d " 
! 				 "- subscriber %.3f/%d\n",
! 				 node->no_id, 
! 				 pm.prov_query_t, pm.prov_query_c, 
! 				 pm.subscr_query_t, pm.prov_query_c);
! 
! 		slon_log(SLON_INFO, 
! 				 "remoteWorkerThread_%d: sync_helper timing: " 
! 				 " large tuples %.3f/%d\n", 
! 				 node->no_id, 
! 				 pm.large_tuples_t, pm.large_tuples_c);
  
  		/*