Merge pull request #1824 from jchavanton/dns_slow_query

core: dns slow queries reporting

src/core/cfg.lex

@@ -309,6 +309,7 @@ DNS_TCP_PREF	dns_tcp_pref|dns_tcp_preference
 DNS_TLS_PREF	dns_tls_pref|dns_tls_preference
 DNS_SCTP_PREF	dns_sctp_pref|dns_sctp_preference
 DNS_RETR_TIME	dns_retr_time
+DNS_SLOW_QUERY_MS	dns_slow_query_ms
 DNS_RETR_NO		dns_retr_no
 DNS_SERVERS_NO	dns_servers_no
 DNS_USE_SEARCH	dns_use_search_list
@@ -723,6 +724,8 @@ IMPORTFILE      "import_file"
 								return DNS_SCTP_PREF; }
 <INITIAL>{DNS_RETR_TIME}	{ count(); yylval.strval=yytext;
 								return DNS_RETR_TIME; }
+<INITIAL>{DNS_SLOW_QUERY_MS}	{ count(); yylval.strval=yytext;
+								return DNS_SLOW_QUERY_MS; }
 <INITIAL>{DNS_RETR_NO}	{ count(); yylval.strval=yytext;
 								return DNS_RETR_NO; }
 <INITIAL>{DNS_SERVERS_NO}	{ count(); yylval.strval=yytext;

src/core/cfg.y

@@ -337,6 +337,7 @@ extern char *default_routename;
 %token DNS_TLS_PREF
 %token DNS_SCTP_PREF
 %token DNS_RETR_TIME
+%token DNS_SLOW_QUERY_MS
 %token DNS_RETR_NO
 %token DNS_SERVERS_NO
 %token DNS_USE_SEARCH
@@ -827,6 +828,8 @@ assign_stm:
 	| DNS_SCTP_PREF error { yyerror("number expected"); }
 	| DNS_RETR_TIME EQUAL NUMBER   { default_core_cfg.dns_retr_time=$3; }
 	| DNS_RETR_TIME error { yyerror("number expected"); }
+	| DNS_SLOW_QUERY_MS EQUAL NUMBER   { default_core_cfg.dns_slow_query_ms=$3; }
+	| DNS_SLOW_QUERY_MS error { yyerror("number expected"); }
 	| DNS_RETR_NO EQUAL NUMBER   { default_core_cfg.dns_retr_no=$3; }
 	| DNS_RETR_NO error { yyerror("number expected"); }
 	| DNS_SERVERS_NO EQUAL NUMBER   { default_core_cfg.dns_servers_no=$3; }

src/core/cfg_core.c

@@ -78,6 +78,7 @@ struct cfg_group_core default_core_cfg = {
 	10,  /*!< tls transport preference (for naptr) */
 	20,  /*!< sctp transport preference (for naptr) */
 	-1, /*!< dns_retr_time */
+	0,  /*!< dns_slow_query_ms */
 	-1, /*!< dns_retr_no */
 	-1, /*!< dns_servers_no */
 	1,  /*!< dns_search_list */
@@ -224,6 +225,8 @@ cfg_def_t core_cfg_def[] = {
 		"sctp protocol preference when doing NAPTR lookups"},
 	{"dns_retr_time",	CFG_VAR_INT,	0, 0, 0, resolv_reinit,
 		"time in s before retrying a dns request"},
+	{"dns_slow_query_ms",	CFG_VAR_INT,	0, 0, 0, resolv_reinit,
+		"max time in ms before a dns request is considered slow"},
 	{"dns_retr_no",		CFG_VAR_INT,	0, 0, 0, resolv_reinit,
 		"number of dns retransmissions before giving up"},
 	{"dns_servers_no",	CFG_VAR_INT,	0, 0, 0, resolv_reinit,

src/core/cfg_core.h

@@ -67,6 +67,7 @@ struct cfg_group_core {
 	int dns_tls_pref;
 	int dns_sctp_pref;
 	int dns_retr_time;
+	int dns_slow_query_ms;
 	int dns_retr_no;
 	int dns_servers_no;
 	int dns_search_list;

src/core/resolve.c

@@ -51,6 +51,8 @@ struct dns_counters_h dns_cnts_h;
 counter_def_t dns_cnt_defs[] =  {
 	{&dns_cnts_h.failed_dns_req, "failed_dns_request", 0, 0, 0,
 		"incremented each time a DNS request has failed."},
+	{&dns_cnts_h.slow_dns_req, "slow_dns_request", 0, 0, 0,
+		"incremented each time a DNS request took longer than dns_slow_query_ms."},
 	{0, 0, 0, 0, 0, 0 }
 };
 
@@ -714,6 +716,8 @@ struct rdata* get_record(char* name, int type, int flags)
 	int name_len;
 	struct rdata* fullname_rd;
 	char c;
+	struct timeval start, stop;
+	int slow_query_ms = cfg_get(core, core_cfg, dns_slow_query_ms);
 
 	name_len=strlen(name);
 
@@ -735,8 +739,21 @@ struct rdata* get_record(char* name, int type, int flags)
 	}
 	fullname_rd=0;
 
+	if (slow_query_ms > 0)
+		gettimeofday(&start, NULL);
+
 	size=dns_func.sr_res_search(name, C_IN, type, buff.buff, sizeof(buff));
 
+	if (slow_query_ms > 0) {
+		gettimeofday(&stop, NULL);
+		int latency_ms = (stop.tv_sec - start.tv_sec)*1000
+                + (stop.tv_usec - start.tv_usec)/1000;
+		if (slow_query_ms < latency_ms) {
+			LOG(cfg_get(core, core_cfg, latency_log), "res_search[%d][%s]elapsed[%dms]\n", type, name, latency_ms);
+			counter_inc(dns_cnts_h.slow_dns_req);
+		}
+	}
+
 	if (unlikely(size<0)) {
 		LM_DBG("lookup(%s, %d) failed\n", name, type);
 		goto not_found;

src/core/resolve.h

@@ -65,10 +65,11 @@
 #define RES_ONLY_TYPE 1   /* return only the specified type records */
 #define RES_AR		  2   /* return also the additional records */
 
-/* counter for failed DNS requests
+/* counter for failed/slow DNS requests
 */
 struct dns_counters_h {
     counter_handle_t failed_dns_req;
+    counter_handle_t slow_dns_req;
 };
 
 extern struct dns_counters_h dns_cnts_h;