core: new core parameter latency_cfg_log

- if set to a log level less or equal than debug parameter, a log
  message with the duration of executing request route or reply route is
  printed to syslog
- default value is L_DBG

cfg.lex

@@ -440,6 +440,7 @@ SERVER_ID     "server_id"
 MAX_RECURSIVE_LEVEL		"max_recursive_level"
 MAX_BRANCHES_PARAM		"max_branches"|"max_branches"
 
+LATENCY_CFG_LOG			latency_cfg_log
 LATENCY_LOG				latency_log
 LATENCY_LIMIT_DB		latency_limit_db
 LATENCY_LIMIT_ACTION	latency_limit_action
@@ -910,6 +911,7 @@ IMPORTFILE      "import_file"
 <INITIAL>{MAX_RECURSIVE_LEVEL}  { count(); yylval.strval=yytext; return MAX_RECURSIVE_LEVEL;}
 <INITIAL>{MAX_BRANCHES_PARAM}  { count(); yylval.strval=yytext; return MAX_BRANCHES_PARAM;}
 <INITIAL>{LATENCY_LOG}  { count(); yylval.strval=yytext; return LATENCY_LOG;}
+<INITIAL>{LATENCY_CFG_LOG}  { count(); yylval.strval=yytext; return LATENCY_CFG_LOG;}
 <INITIAL>{MSG_TIME}  { count(); yylval.strval=yytext; return MSG_TIME;}
 <INITIAL>{ONSEND_RT_REPLY}	{ count(); yylval.strval=yytext; return ONSEND_RT_REPLY; }
 <INITIAL>{LATENCY_LIMIT_DB}  { count(); yylval.strval=yytext; return LATENCY_LIMIT_DB;}

cfg.y

@@ -476,6 +476,7 @@ extern char *default_routename;
 %token SERVER_ID
 %token MAX_RECURSIVE_LEVEL
 %token MAX_BRANCHES_PARAM
+%token LATENCY_CFG_LOG
 %token LATENCY_LOG
 %token LATENCY_LIMIT_DB
 %token LATENCY_LIMIT_ACTION
@@ -1521,6 +1522,8 @@ assign_stm:
     | MAX_BRANCHES_PARAM EQUAL NUMBER { sr_dst_max_branches = $3; }
     | LATENCY_LOG EQUAL NUMBER { default_core_cfg.latency_log=$3; }
 	| LATENCY_LOG EQUAL error  { yyerror("number  expected"); }
+    | LATENCY_CFG_LOG EQUAL NUMBER { default_core_cfg.latency_cfg_log=$3; }
+	| LATENCY_CFG_LOG EQUAL error  { yyerror("number  expected"); }
     | LATENCY_LIMIT_DB EQUAL NUMBER { default_core_cfg.latency_limit_db=$3; }
 	| LATENCY_LIMIT_DB EQUAL error  { yyerror("number  expected"); }
     | LATENCY_LIMIT_ACTION EQUAL NUMBER { default_core_cfg.latency_limit_action=$3; }
@@ -1531,7 +1534,7 @@ assign_stm:
 	| ONSEND_RT_REPLY EQUAL error { yyerror("int value expected"); }
 	| UDP_MTU EQUAL NUMBER { default_core_cfg.udp_mtu=$3; }
 	| UDP_MTU EQUAL error { yyerror("number expected"); }
-	| FORCE_RPORT EQUAL NUMBER 
+	| FORCE_RPORT EQUAL NUMBER
 		{ default_core_cfg.force_rport=$3; fix_global_req_flags(0, 0); }
 	| FORCE_RPORT EQUAL error { yyerror("boolean value expected"); }
 	| UDP_MTU_TRY_PROTO EQUAL proto

cfg_core.c

@@ -116,6 +116,7 @@ struct cfg_group_core default_core_cfg = {
 	0, /*!< mem_safety - 0 disabled */
 	0, /*!< mem_join - 0 disabled */
 	L_ERR, /*!< corelog */
+	L_DBG, /*!< latency cfg log */
 	L_ERR, /*!< latency log */
 	0, /*!< latency limit db */
 	0 /*!< latency limit action */
@@ -128,7 +129,7 @@ static int check_raw_sock_support(void* cfg_h, str* gname, str* name,
 									void** v)
 {
 	int val;
-	
+
 	val = (int)(long)(*v);
 #ifndef USE_RAW_SOCKS
 	if (val > 0) {
@@ -314,6 +315,8 @@ cfg_def_t core_cfg_def[] = {
 		"join free memory fragments"},
 	{"corelog",		CFG_VAR_INT|CFG_ATOMIC,	0, 0, 0, 0,
 		"log level for non-critical core error messages"},
+	{"latency_cfg_log",		CFG_VAR_INT|CFG_ATOMIC,	0, 0, 0, 0,
+		"log level for printing latency of routing blocks"},
 	{"latency_log",		CFG_VAR_INT|CFG_ATOMIC,	0, 0, 0, 0,
 		"log level for latency limits alert messages"},
 	{"latency_limit_db",		CFG_VAR_INT|CFG_ATOMIC,	0, 0, 0, 0,

cfg_core.h

@@ -104,6 +104,7 @@ struct cfg_group_core {
 	int mem_safety; /*!< memory safety control option */
 	int mem_join; /*!< memory free fragments join option */
 	int corelog; /*!< log level for non-critcal core error messages */
+	int latency_cfg_log; /*!< log level for printing latency of routing blocks */
 	int latency_log; /*!< log level for latency limits messages */
 	int latency_limit_db; /*!< alert limit of running db commands */
 	int latency_limit_action; /*!< alert limit of running cfg actions */

receive.c

@@ -121,10 +121,13 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
 	int ret;
 #ifdef STATS
 	int skipped = 1;
+	int stats_on = 1;
+#else
+	int stats_on = 0;
+#endif
 	struct timeval tvb, tve;
 	struct timezone tz;
-	unsigned int diff;
-#endif
+	unsigned int diff = 0;
 	str inb;
 	sr_net_info_t netinfo;
 	sr_kemi_eng_t *keng = NULL;
@@ -222,9 +225,10 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
 
 	/*	skip: */
 		LM_DBG("preparing to run routing scripts...\n");
-#ifdef  STATS
-		gettimeofday( & tvb, &tz );
-#endif
+		if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
+				|| stats_on==1) {
+			gettimeofday( & tvb, &tz );
+		}
 		/* execute pre-script callbacks, if any; -jiri */
 		/* if some of the callbacks said not to continue with
 		 * script processing, don't do so
@@ -256,14 +260,18 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
 			}
 		}
 
+		if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
+				|| stats_on==1) {
+			gettimeofday( & tve, &tz );
+			diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
+			LOG(cfg_get(core, core_cfg, latency_cfg_log),
+					"request-route executed in: %d usec\n", diff);
 #ifdef STATS
-		gettimeofday( & tve, &tz );
-		diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
-		stats->processed_requests++;
-		stats->acc_req_time += diff;
-		LM_DBG("successfully ran routing scripts...(%d usec)\n", diff);
-		STATS_RX_REQUEST( msg->first_line.u.request.method_value );
+			stats->processed_requests++;
+			stats->acc_req_time += diff;
+			STATS_RX_REQUEST( msg->first_line.u.request.method_value );
 #endif
+		}
 
 		/* execute post request-script callbacks */
 		exec_post_script_cb(msg, REQUEST_CB_TYPE);
@@ -276,8 +284,11 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
 			goto error02;
 		}
 
+		if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
+				|| stats_on==1) {
+			gettimeofday( & tvb, &tz );
+		}
 #ifdef STATS
-		gettimeofday( & tvb, &tz );
 		STATS_RX_RESPONSE ( msg->first_line.u.reply.statuscode / 100 );
 #endif
 
@@ -322,13 +333,17 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
 		/* send the msg */
 		forward_reply(msg);
 	skip_send_reply:
+		if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
+				|| stats_on==1) {
+			gettimeofday( & tve, &tz );
+			diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
+			LOG(cfg_get(core, core_cfg, latency_cfg_log),
+					"reply-route executed in: %d usec\n", diff);
 #ifdef STATS
-		gettimeofday( & tve, &tz );
-		diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
-		stats->processed_responses++;
-		stats->acc_res_time+=diff;
-		LM_DBG("successfully ran reply processing...(%d usec)\n", diff);
+			stats->processed_responses++;
+			stats->acc_res_time+=diff;
 #endif
+		}
 
 		/* execute post reply-script callbacks */
 		exec_post_script_cb(msg, ONREPLY_CB_TYPE);