statistics-interval config setting.

git-svn-id: file:///svn/unbound/trunk@917 be551aaa-1e26-0410-a405-d3ace91eadb9

daemon/stats.c

@@ -46,7 +46,7 @@
 
 void server_stats_init(struct server_stats* stats)
 {
-	memset(stats, 0, sizeof(stats));
+	memset(stats, 0, sizeof(*stats));
 }
 
 void server_stats_querymiss(struct server_stats* stats, struct worker* worker)

daemon/worker.c

@@ -163,6 +163,23 @@ worker_mem_report(struct worker* ATTR_UNUSED(worker),
 		(unsigned)infra, (unsigned)iter, (unsigned)val, (unsigned)ac, 
 		(unsigned)superac, (unsigned)me);
 	debug_total_mem(total);
+#else /* no UNBOUND_ALLOC_STATS */
+	size_t val = 0;
+	int i;
+	if(verbosity < VERB_DETAIL)
+		return;
+	for(i=0; i<worker->env.mesh->mods.num; i++) {
+		log_assert(fptr_whitelist_mod_get_mem(worker->env.mesh->
+			mods.mod[i]->get_mem));
+		if(strcmp(worker->env.mesh->mods.mod[i]->name, "validator")==0)
+			val += (*worker->env.mesh->mods.mod[i]->get_mem)
+				(&worker->env, i);
+	}
+	verbose(VERB_DETAIL, "cache memory msg=%u rrset=%u infra=%u val=%u",
+		slabhash_get_mem(worker->env.msg_cache),
+		slabhash_get_mem(&worker->env.rrset_cache->table),
+		infra_get_mem(worker->env.infra_cache),
+		val);
 #endif /* UNBOUND_ALLOC_STATS */
 }
 
@@ -842,6 +859,30 @@ worker_sighandler(int sig, void* arg)
 	}
 }
 
+/** restart statistics timer for worker, if enabled */
+static void
+worker_restart_timer(struct worker* worker)
+{
+	if(worker->env.cfg->stat_interval > 0) {
+		struct timeval tv;
+		tv.tv_sec = worker->env.cfg->stat_interval;
+		tv.tv_usec = 0;
+		comm_timer_set(worker->stat_timer, &tv);
+	}
+}
+
+void worker_stat_timer_cb(void* arg)
+{
+	struct worker* worker = (struct worker*)arg;
+	mesh_stats(worker->env.mesh, "mesh has");
+	server_stats_log(&worker->stats, worker->thread_num);
+	worker_mem_report(worker, NULL);
+	server_stats_init(&worker->stats);
+	mesh_stats_clear(worker->env.mesh);
+	/* start next timer */
+	worker_restart_timer(worker);
+}
+
 struct worker* 
 worker_create(struct daemon* daemon, int id)
 {
@@ -946,6 +987,12 @@ worker_init(struct worker* worker, struct config_file *cfg,
 			return 0;
 		}
 	}
+	worker->stat_timer = comm_timer_create(worker->base, 
+		worker_stat_timer_cb, worker);
+	if(!worker->stat_timer) {
+		log_err("could not create statistics timer");
+	}
+
 	/* we use the msg_buffer_size as a good estimate for what the 
 	 * user wants for memory usage sizes */
 	worker->scratchpad = regional_create_custom(cfg->msg_buffer_size);
@@ -978,6 +1025,10 @@ worker_init(struct worker* worker, struct config_file *cfg,
 		return 0;
 	}
 	worker_mem_report(worker, NULL);
+	/* if statistics enabled start timer */
+	verbose(VERB_ALGO, "set statistics interval %d secs", 
+		worker->env.cfg->stat_interval);
+	worker_restart_timer(worker);
 	return 1;
 }
 
@@ -1003,6 +1054,7 @@ worker_delete(struct worker* worker)
 	outside_network_delete(worker->back);
 	comm_signal_delete(worker->comsig);
 	comm_point_delete(worker->cmd_com);
+	comm_timer_delete(worker->stat_timer);
 	comm_base_delete(worker->base);
 	ub_randfree(worker->rndstate);
 	/* close fds after deleting commpoints, to be sure.

daemon/worker.h

@@ -90,6 +90,8 @@ struct worker {
 	struct comm_signal* comsig;
 	/** commpoint to listen to commands. */
 	struct comm_point* cmd_com;
+	/** timer for statistics */
+	struct comm_timer* stat_timer;
 
 	/** number of requests that can be handled by this worker */
 	size_t request_size;
@@ -214,4 +216,7 @@ int worker_handle_service_reply(struct comm_point* c, void* arg, int error,
 /** cleanup the cache to remove all rrset IDs from it, arg is worker */
 void worker_alloc_cleanup(void* arg);
 
+/** statistics timer callback handler */
+void worker_stat_timer_cb(void* arg);
+
 #endif /* DAEMON_WORKER_H */

doc/Changelog

@@ -1,3 +1,6 @@
+5 February 2008: Wouter
+	- statistics-interval: seconds option added.
+
 31 January 2008: Wouter
 	- bg thread/process reads and writes the pipe nonblocking all the time
 	  so that even if the pipe is buffered or so, the bg thread does not

doc/example.conf

@@ -15,6 +15,10 @@ server:
 	# verbosity number, 0 is least verbose. 1 is default.
 	verbosity: 1
 
+	# print statistics to the log (for every thread) every N seconds.
+	# Set to "" or 0 to disable. Default is disabled.
+	# statistics-interval: 0
+
 	# number of threads to create. 1 disables threading.
 	# num-threads: 1
 

doc/unbound.conf.5

@@ -83,6 +83,10 @@ Default is level 1. The verbosity can also be increased from the commandline,
 see
 \fIunbound\fR(8).
 .TP
+.B statistics-interval: \fI<seconds>
+The number of seconds between printing statistics to the log for every thread.
+Disable with value 0 or "". Default is disabled. 
+.TP
 .B num\-threads: \fI<number>
 The number of threads to create to serve clients. Use 1 for no threading.
 .TP

libunbound/worker.c

@@ -1014,3 +1014,8 @@ acl_list_cmp(const void* ATTR_UNUSED(k1), const void* ATTR_UNUSED(k2))
 	log_assert(0);
 	return 0;
 }
+
+void worker_stat_timer_cb(void* ATTR_UNUSED(arg))
+{
+	log_assert(0);
+}

services/mesh.c

@@ -785,6 +785,17 @@ mesh_stats(struct mesh_area* mesh, const char* str)
 	}
 }
 
+void 
+mesh_stats_clear(struct mesh_area* mesh)
+{
+	if(!mesh)
+		return;
+	mesh->replies_sent = 0;
+	mesh->replies_sum_wait.tv_sec = 0;
+	mesh->replies_sum_wait.tv_usec = 0;
+	timehist_clear(mesh->histogram);
+}
+
 size_t 
 mesh_get_mem(struct mesh_area* mesh)
 {

services/mesh.h

@@ -415,6 +415,12 @@ void mesh_run(struct mesh_area* mesh, struct mesh_state* mstate,
  */
 void mesh_stats(struct mesh_area* mesh, const char* str);
 
+/**
+ * Clear the stats that the mesh keeps (number of queries serviced)
+ * @param mesh: the mesh
+ */
+void mesh_stats_clear(struct mesh_area* mesh);
+
 /**
  * Print all the states in the mesh to the log.
  * @param mesh: the mesh to print all states of.

smallapp/worker_cb.c

@@ -155,3 +155,8 @@ int context_query_cmp(const void* ATTR_UNUSED(a), const void* ATTR_UNUSED(b))
 	log_assert(0);
 	return 0;
 }
+
+void worker_stat_timer_cb(void* ATTR_UNUSED(arg))
+{
+	log_assert(0);
+}

testcode/fake_event.c

@@ -1066,4 +1066,26 @@ int serviced_cmp(const void* ATTR_UNUSED(a), const void* ATTR_UNUSED(b))
 	return 0;
 }
 
+/* no statistics timers in testbound */
+struct comm_timer* comm_timer_create(struct comm_base* ATTR_UNUSED(base), 
+	void (*cb)(void*), void* ATTR_UNUSED(cb_arg))
+{
+	(void)cb;
+	return malloc(1);
+}
+
+void comm_timer_disable(struct comm_timer* ATTR_UNUSED(timer))
+{
+}
+
+void comm_timer_set(struct comm_timer* ATTR_UNUSED(timer), 
+	struct timeval* ATTR_UNUSED(tv))
+{
+}
+
+void comm_timer_delete(struct comm_timer* timer)
+{
+	free(timer);
+}
+
 /*********** End of Dummy routines ***********/

util/config_file.c

@@ -70,6 +70,7 @@ config_create()
 		return NULL;
 	/* the defaults if no config is present */
 	cfg->verbosity = 1;
+	cfg->stat_interval = 0;
 	cfg->num_threads = 1;
 	cfg->port = UNBOUND_DNS_PORT;
 	cfg->do_ip4 = 1;

util/config_file.h

@@ -52,6 +52,8 @@ struct config_str2list;
 struct config_file {
 	/** verbosity level as specified in the config file */
 	int verbosity;
+	/** statistics interval (in seconds) */
+	int stat_interval;
 
 	/** number of threads to create */
 	int num_threads;

util/configlexer.lex

@@ -165,6 +165,7 @@ val-nsec3-keysize-iterations{COLON}	{ YDOUT; return VAR_VAL_NSEC3_KEYSIZE_ITERAT
 use-syslog{COLON}	{ YDOUT; return VAR_USE_SYSLOG;}
 local-zone{COLON}	{ YDOUT; return VAR_LOCAL_ZONE;}
 local-data{COLON}	{ YDOUT; return VAR_LOCAL_DATA;}
+statistics-interval{COLON}	{ YDOUT; return VAR_STATISTICS_INTERVAL;}
 {NEWLINE}		{ LEXOUT(("NL\n")); cfg_parser->line++;}
 
 	/* Quoted strings. Strip leading and ending quotes */

util/configparser.h

@@ -112,7 +112,8 @@
      VAR_ACCESS_CONTROL = 328,
      VAR_LOCAL_ZONE = 329,
      VAR_LOCAL_DATA = 330,
-     VAR_INTERFACE_AUTOMATIC = 331
+     VAR_INTERFACE_AUTOMATIC = 331,
+     VAR_STATISTICS_INTERVAL = 332
    };
 #endif
 /* Tokens.  */
@@ -190,6 +191,7 @@
 #define VAR_LOCAL_ZONE 329
 #define VAR_LOCAL_DATA 330
 #define VAR_INTERFACE_AUTOMATIC 331
+#define VAR_STATISTICS_INTERVAL 332
 
 
 
@@ -201,7 +203,7 @@ typedef union YYSTYPE
 	char*	str;
 }
 /* Line 1489 of yacc.c.  */
-#line 205 "util/configparser.h"
+#line 207 "util/configparser.h"
 	YYSTYPE;
 # define yystype YYSTYPE /* obsolescent; will be withdrawn */
 # define YYSTYPE_IS_DECLARED 1

util/configparser.y

@@ -88,6 +88,7 @@ extern struct config_parser_state* cfg_parser;
 %token VAR_OUTGOING_INTERFACE VAR_ROOT_HINTS VAR_DO_NOT_QUERY_LOCALHOST
 %token VAR_CACHE_MAX_TTL VAR_HARDEN_DNNSEC_STRIPPED VAR_ACCESS_CONTROL
 %token VAR_LOCAL_ZONE VAR_LOCAL_DATA VAR_INTERFACE_AUTOMATIC
+%token VAR_STATISTICS_INTERVAL
 
 %%
 toplevelvars: /* empty */ | toplevelvars toplevelvar ;
@@ -126,7 +127,8 @@ content_server: server_num_threads | server_verbosity | server_port |
 	server_use_syslog | server_outgoing_interface | server_root_hints |
 	server_do_not_query_localhost | server_cache_max_ttl |
 	server_harden_dnssec_stripped | server_access_control |
-	server_local_zone | server_local_data | server_interface_automatic
+	server_local_zone | server_local_data | server_interface_automatic |
+	server_statistics_interval
 	;
 stubstart: VAR_STUB_ZONE
 	{
@@ -178,6 +180,17 @@ server_verbosity: VAR_VERBOSITY STRING
 		free($2);
 	}
 	;
+server_statistics_interval: VAR_STATISTICS_INTERVAL STRING 
+	{ 
+		OUTYY(("P(server_statistics_interval:%s)\n", $2)); 
+		if(strcmp($2, "") == 0 || strcmp($2, "0") == 0)
+			cfg_parser->cfg->stat_interval = 0;
+		else if(atoi($2) == 0)
+			yyerror("number expected");
+		else cfg_parser->cfg->stat_interval = atoi($2);
+		free($2);
+	}
+	;
 server_port: VAR_PORT STRING
 	{
 		OUTYY(("P(server_port:%s)\n", $2));

util/fptr_wlist.c

@@ -85,6 +85,7 @@ fptr_whitelist_comm_timer(void (*fptr)(void*))
 {
 	if(fptr == &pending_udp_timer_cb) return 1;
 	else if(fptr == &outnet_tcptimer) return 1;
+	else if(fptr == &worker_stat_timer_cb) return 1;
 	return 0;
 }
 

util/netevent.c

@@ -129,7 +129,9 @@ comm_base_delete(struct comm_base* b)
 {
 	if(!b)
 		return;
-#if defined(HAVE_EVENT_BASE_FREE) && defined(HAVE_EVENT_BASE_ONCE)
+#ifdef USE_MINI_EVENT
+	event_base_free(b->eb->base);
+#elif defined(HAVE_EVENT_BASE_FREE) && defined(HAVE_EVENT_BASE_ONCE)
 	/* only libevent 1.2+ has it, but in 1.2 it is broken - 
 	   assertion fails on signal handling ev that is not deleted
  	   in libevent 1.3c (event_base_once appears) this is fixed. */
@@ -1308,6 +1310,8 @@ comm_timer_set(struct comm_timer* timer, struct timeval* tv)
 	log_assert(tv);
 	if(timer->ev_timer->enabled)
 		comm_timer_disable(timer);
+	event_set(&timer->ev_timer->ev, -1, EV_PERSIST|EV_TIMEOUT,
+		comm_timer_callback, timer);
 	if(evtimer_add(&timer->ev_timer->ev, tv) != 0)
 		log_err("comm_timer_set: evtimer_add failed.");
 	timer->ev_timer->enabled = 1;

util/timehist.c

@@ -102,6 +102,13 @@ void timehist_delete(struct timehist* hist)
 	free(hist);
 }
 
+void timehist_clear(struct timehist* hist)
+{
+	size_t i;
+	for(i=0; i<hist->num; i++)
+		hist->buckets[i].count = 0;
+}
+
 /** histogram compare of time values */
 static int
 timeval_smaller(struct timeval* x, struct timeval* y)

util/timehist.h

@@ -76,6 +76,12 @@ struct timehist* timehist_setup();
  */
 void timehist_delete(struct timehist* hist);
 
+/**
+ * Clear histogram
+ * @param hist: to clear all data from
+ */
+void timehist_clear(struct timehist* hist);
+
 /**
  * Add time value to histogram.
  * @param hist: histogram