Browse code

core: new parameters to control and alert on time consuming ops

- latency_log - log level to print the messages related to latency
- latency_limit_db - limit of latency in ms for db operations. If a db
operation executed via DB API v1 takes longer that its value, a
message is printed in the logs, showing the first 50 characters of the
db query
- latency_limit_action - limit of latency in ms for config actions. If a
config action executed by cfg interpreter takes longer than its value,
a message is printed in the logs, showing config path, line and action
name when it is a module function, as well as intenal action id

Daniel-Constantin Mierla authored on 25/03/2012 11:39:20
Showing 7 changed files
... ...
@@ -1580,6 +1580,7 @@ int run_actions(struct run_act_ctx* h, struct action* a, struct sip_msg* msg)
1580 1580
 	struct action* t;
1581 1581
 	int ret;
1582 1582
 	struct sr_module *mod;
1583
+	unsigned int ms;
1583 1584
 
1584 1585
 	ret=E_UNSPEC;
1585 1586
 	h->rec_lev++;
... ...
@@ -1609,7 +1610,21 @@ int run_actions(struct run_act_ctx* h, struct action* a, struct sip_msg* msg)
1609 1609
 	}
1610 1610
 
1611 1611
 	for (t=a; t!=0; t=t->next){
1612
+		if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0))
1613
+			ms = TICKS_TO_MS(get_ticks_raw());
1612 1614
 		ret=do_action(h, t, msg);
1615
+		if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) {
1616
+			ms = TICKS_TO_MS(get_ticks_raw()) - ms;
1617
+			if(ms >= cfg_get(core, core_cfg, latency_limit_action)) {
1618
+				LOG(cfg_get(core, core_cfg, latency_log),
1619
+						"alert - action [%s (%d)]"
1620
+						" cfg [%s:%d] took too long [%u ms]\n",
1621
+						is_mod_func(t) ?
1622
+							((cmd_export_common_t*)(t->val[0].u.data))->name
1623
+							: "corefunc",
1624
+						t->type, (t->cfile)?t->cfile:"", t->cline, ms);
1625
+			}
1626
+		}
1613 1627
 		/* break, return or drop/exit stop execution of the current
1614 1628
 		   block */
1615 1629
 		if (unlikely(h->run_flags & (BREAK_R_F|RETURN_R_F|EXIT_R_F))){
... ...
@@ -503,6 +503,10 @@ STUN_ALLOW_FP "stun_allow_fp"
503 503
 
504 504
 SERVER_ID     "server_id"
505 505
 
506
+LATENCY_LOG				latency_log
507
+LATENCY_LIMIT_DB		latency_limit_db
508
+LATENCY_LIMIT_ACTION	latency_limit_action
509
+
506 510
 CFG_DESCRIPTION		"description"|"descr"|"desc"
507 511
 
508 512
 LOADMODULE	loadmodule
... ...
@@ -965,6 +969,9 @@ IMPORTFILE      "import_file"
965 965
 <INITIAL>{HTTP_REPLY_HACK}		{	count(); yylval.strval=yytext;
966 966
 									return HTTP_REPLY_HACK; }
967 967
 <INITIAL>{SERVER_ID}  { count(); yylval.strval=yytext; return SERVER_ID;}
968
+<INITIAL>{LATENCY_LOG}  { count(); yylval.strval=yytext; return LATENCY_LOG;}
969
+<INITIAL>{LATENCY_LIMIT_DB}  { count(); yylval.strval=yytext; return LATENCY_LIMIT_DB;}
970
+<INITIAL>{LATENCY_LIMIT_ACTION}  { count(); yylval.strval=yytext; return LATENCY_LIMIT_ACTION;}
968 971
 <INITIAL>{CFG_DESCRIPTION}	{ count(); yylval.strval=yytext; return CFG_DESCRIPTION; }
969 972
 <INITIAL>{LOADMODULE}	{ count(); yylval.strval=yytext; return LOADMODULE; }
970 973
 <INITIAL>{LOADPATH}		{ count(); yylval.strval=yytext; return LOADPATH; }
... ...
@@ -559,6 +559,9 @@ extern char *finame;
559 559
 %token HTTP_REPLY_HACK
560 560
 %token CFG_DESCRIPTION
561 561
 %token SERVER_ID
562
+%token LATENCY_LOG
563
+%token LATENCY_LIMIT_DB
564
+%token LATENCY_LIMIT_ACTION
562 565
 
563 566
 %token FLAGS_DECL
564 567
 %token AVPFLAGS_DECL
... ...
@@ -1671,6 +1674,12 @@ assign_stm:
1671 1671
 	| STUN_ALLOW_FP EQUAL NUMBER { IF_STUN(stun_allow_fp=$3) ; }
1672 1672
 	| STUN_ALLOW_FP EQUAL error{ yyerror("number expected"); }
1673 1673
     | SERVER_ID EQUAL NUMBER { server_id=$3; }
1674
+    | LATENCY_LOG EQUAL NUMBER { default_core_cfg.latency_log=$3; }
1675
+	| LATENCY_LOG EQUAL error  { yyerror("number  expected"); }
1676
+    | LATENCY_LIMIT_DB EQUAL NUMBER { default_core_cfg.latency_limit_db=$3; }
1677
+	| LATENCY_LIMIT_DB EQUAL error  { yyerror("number  expected"); }
1678
+    | LATENCY_LIMIT_ACTION EQUAL NUMBER { default_core_cfg.latency_limit_action=$3; }
1679
+	| LATENCY_LIMIT_ACTION EQUAL error  { yyerror("number  expected"); }
1674 1680
 	| UDP_MTU EQUAL NUMBER { default_core_cfg.udp_mtu=$3; }
1675 1681
 	| UDP_MTU EQUAL error { yyerror("number expected"); }
1676 1682
 	| FORCE_RPORT EQUAL NUMBER 
... ...
@@ -121,7 +121,10 @@ struct cfg_group_core default_core_cfg = {
121 121
 	L_DBG, /*!< memlog */
122 122
 	3, /*!< mem_summary -flags: 0 off, 1 pkg_status, 2 shm_status,
123 123
 		4 pkg_sums, 8 shm_sums, 16 short_status */
124
-	L_ERR /*!< corelog */
124
+	L_ERR, /*!< corelog */
125
+	L_ERR, /*!< latency log */
126
+	0, /*!< latency limit db */
127
+	0 /*!< latency limit action */
125 128
 };
126 129
 
127 130
 void	*core_cfg = &default_core_cfg;
... ...
@@ -311,5 +314,11 @@ cfg_def_t core_cfg_def[] = {
311 311
 		" 16 - short status instead of dump" },
312 312
 	{"corelog",		CFG_VAR_INT|CFG_ATOMIC,	0, 0, 0, 0,
313 313
 		"log level for non-critical core error messages"},
314
+	{"latency_log",		CFG_VAR_INT|CFG_ATOMIC,	0, 0, 0, 0,
315
+		"log level for latency limits alert messages"},
316
+	{"latency_limit_db",		CFG_VAR_INT|CFG_ATOMIC,	0, 0, 0, 0,
317
+		"limit is ms for alerting on time consuming db commands"},
318
+	{"latency_limit_action",		CFG_VAR_INT|CFG_ATOMIC,	0, 0, 0, 0,
319
+		"limit is ms for alerting on time consuming config actions"},
314 320
 	{0, 0, 0, 0, 0, 0}
315 321
 };
... ...
@@ -109,6 +109,9 @@ struct cfg_group_core {
109 109
 	int memlog; /*!< log level for memory status/summary info */
110 110
 	int mem_summary; /*!< display memory status/summary info on exit */
111 111
 	int corelog; /*!< log level for non-critcal core error messages */
112
+	int latency_log; /*!< log level for latency limits messages */
113
+	int latency_limit_db; /*!< alert limit of running db commands */
114
+	int latency_limit_action; /*!< alert limit of running cfg actions */
112 115
 };
113 116
 
114 117
 extern struct cfg_group_core default_core_cfg;
... ...
@@ -38,10 +38,34 @@
38 38
 #include "db_ut.h"
39 39
 #include "db_query.h"
40 40
 #include "../../globals.h"
41
+#include "../../timer.h"
41 42
 
42 43
 static str  sql_str;
43 44
 static char *sql_buf = NULL;
44 45
 
46
+static inline int db_do_submit_query(const db1_con_t* _h, const str *_query,
47
+		int (*submit_query)(const db1_con_t*, const str*))
48
+{
49
+	int ret;
50
+	unsigned int ms;
51
+
52
+	if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0))
53
+		ms = TICKS_TO_MS(get_ticks_raw());
54
+
55
+	ret = submit_query(_h, _query);
56
+
57
+	if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) {
58
+		ms = TICKS_TO_MS(get_ticks_raw()) - ms;
59
+		if(ms >= cfg_get(core, core_cfg, latency_limit_action)) {
60
+				LOG(cfg_get(core, core_cfg, latency_log),
61
+					"alert - query execution too long [%u ms] for [%.*s]\n",
62
+				   ms, _query->len<50?_query->len:50, _query->s);
63
+		}
64
+	}
65
+
66
+	return ret;
67
+}
68
+
45 69
 int db_do_query(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _op,
46 70
 	const db_val_t* _v, const db_key_t* _c, const int _n, const int _nc,
47 71
 	const db_key_t _o, db1_res_t** _r, int (*val2str) (const db1_con_t*,
... ...
@@ -99,7 +123,7 @@ int db_do_query(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _op,
99 99
 	sql_str.s = sql_buf;
100 100
 	sql_str.len = off;
101 101
 
102
-	if (submit_query(_h, &sql_str) < 0) {
102
+	if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
103 103
 		LM_ERR("error while submitting query\n");
104 104
 		return -2;
105 105
 	}
... ...
@@ -128,7 +152,7 @@ int db_do_raw_query(const db1_con_t* _h, const str* _s, db1_res_t** _r,
128 128
 		return -1;
129 129
 	}
130 130
 
131
-	if (submit_query(_h, _s) < 0) {
131
+	if (db_do_submit_query(_h, _s, submit_query) < 0) {
132 132
 		LM_ERR("error while submitting query\n");
133 133
 		return -2;
134 134
 	}
... ...
@@ -182,7 +206,7 @@ int db_do_insert_cmd(const db1_con_t* _h, const db_key_t* _k, const db_val_t* _v
182 182
 	sql_str.s = sql_buf;
183 183
 	sql_str.len = off;
184 184
 
185
-	if (submit_query(_h, &sql_str) < 0) {
185
+	if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
186 186
 	        LM_ERR("error while submitting query\n");
187 187
 		return -2;
188 188
 	}
... ...
@@ -238,7 +262,7 @@ int db_do_delete(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _o,
238 238
 	sql_str.s = sql_buf;
239 239
 	sql_str.len = off;
240 240
 
241
-	if (submit_query(_h, &sql_str) < 0) {
241
+	if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
242 242
 		LM_ERR("error while submitting query\n");
243 243
 		return -2;
244 244
 	}
... ...
@@ -284,7 +308,7 @@ int db_do_update(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _o,
284 284
 	sql_str.s = sql_buf;
285 285
 	sql_str.len = off;
286 286
 
287
-	if (submit_query(_h, &sql_str) < 0) {
287
+	if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
288 288
 		LM_ERR("error while submitting query\n");
289 289
 		return -2;
290 290
 	}
... ...
@@ -330,7 +354,7 @@ int db_do_replace(const db1_con_t* _h, const db_key_t* _k, const db_val_t* _v,
330 330
 	sql_str.s = sql_buf;
331 331
 	sql_str.len = off;
332 332
 
333
-	if (submit_query(_h, &sql_str) < 0) {
333
+	if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
334 334
 	        LM_ERR("error while submitting query\n");
335 335
 		return -2;
336 336
 	}
... ...
@@ -119,6 +119,9 @@ enum action_type{
119 119
 		CFG_SELECT_T,
120 120
 		CFG_RESET_T
121 121
 };
122
+
123
+#define is_mod_func(a) ((a)->type>=MODULE0_T && (a)->type<=MODULEX_RVE_T)
124
+
122 125
 /* parameter types for actions or types for expression right operands
123 126
    (WARNING right operands only, not working for left operands) */
124 127
 enum _operand_subtype{