Module: sip-router Branch: master Commit: 930aba2973c19370a5d50aac2661be66e9aacbc3 URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=930aba29...
Author: Daniel-Constantin Mierla miconda@gmail.com Committer: Daniel-Constantin Mierla miconda@gmail.com Date: Sun Mar 25 13:39:20 2012 +0200
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
---
action.c | 15 +++++++++++++++ cfg.lex | 7 +++++++ cfg.y | 9 +++++++++ cfg_core.c | 11 ++++++++++- cfg_core.h | 3 +++ lib/srdb1/db_query.c | 36 ++++++++++++++++++++++++++++++------ route_struct.h | 3 +++ 7 files changed, 77 insertions(+), 7 deletions(-)
diff --git a/action.c b/action.c index e044f65..6178dd7 100644 --- a/action.c +++ b/action.c @@ -1580,6 +1580,7 @@ int run_actions(struct run_act_ctx* h, struct action* a, struct sip_msg* msg) struct action* t; int ret; struct sr_module *mod; + unsigned int ms;
ret=E_UNSPEC; h->rec_lev++; @@ -1609,7 +1610,21 @@ int run_actions(struct run_act_ctx* h, struct action* a, struct sip_msg* msg) }
for (t=a; t!=0; t=t->next){ + if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) + ms = TICKS_TO_MS(get_ticks_raw()); ret=do_action(h, t, msg); + if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) { + ms = TICKS_TO_MS(get_ticks_raw()) - ms; + if(ms >= cfg_get(core, core_cfg, latency_limit_action)) { + LOG(cfg_get(core, core_cfg, latency_log), + "alert - action [%s (%d)]" + " cfg [%s:%d] took too long [%u ms]\n", + is_mod_func(t) ? + ((cmd_export_common_t*)(t->val[0].u.data))->name + : "corefunc", + t->type, (t->cfile)?t->cfile:"", t->cline, ms); + } + } /* break, return or drop/exit stop execution of the current block */ if (unlikely(h->run_flags & (BREAK_R_F|RETURN_R_F|EXIT_R_F))){ diff --git a/cfg.lex b/cfg.lex index 00a55e0..2d1494b 100644 --- a/cfg.lex +++ b/cfg.lex @@ -503,6 +503,10 @@ STUN_ALLOW_FP "stun_allow_fp"
SERVER_ID "server_id"
+LATENCY_LOG latency_log +LATENCY_LIMIT_DB latency_limit_db +LATENCY_LIMIT_ACTION latency_limit_action + CFG_DESCRIPTION "description"|"descr"|"desc"
LOADMODULE loadmodule @@ -965,6 +969,9 @@ IMPORTFILE "import_file" <INITIAL>{HTTP_REPLY_HACK} { count(); yylval.strval=yytext; return HTTP_REPLY_HACK; } <INITIAL>{SERVER_ID} { count(); yylval.strval=yytext; return SERVER_ID;} +<INITIAL>{LATENCY_LOG} { count(); yylval.strval=yytext; return LATENCY_LOG;} +<INITIAL>{LATENCY_LIMIT_DB} { count(); yylval.strval=yytext; return LATENCY_LIMIT_DB;} +<INITIAL>{LATENCY_LIMIT_ACTION} { count(); yylval.strval=yytext; return LATENCY_LIMIT_ACTION;} <INITIAL>{CFG_DESCRIPTION} { count(); yylval.strval=yytext; return CFG_DESCRIPTION; } <INITIAL>{LOADMODULE} { count(); yylval.strval=yytext; return LOADMODULE; } <INITIAL>{LOADPATH} { count(); yylval.strval=yytext; return LOADPATH; } diff --git a/cfg.y b/cfg.y index 9edd0fde..274e1e8 100644 --- a/cfg.y +++ b/cfg.y @@ -559,6 +559,9 @@ extern char *finame; %token HTTP_REPLY_HACK %token CFG_DESCRIPTION %token SERVER_ID +%token LATENCY_LOG +%token LATENCY_LIMIT_DB +%token LATENCY_LIMIT_ACTION
%token FLAGS_DECL %token AVPFLAGS_DECL @@ -1671,6 +1674,12 @@ assign_stm: | STUN_ALLOW_FP EQUAL NUMBER { IF_STUN(stun_allow_fp=$3) ; } | STUN_ALLOW_FP EQUAL error{ yyerror("number expected"); } | SERVER_ID EQUAL NUMBER { server_id=$3; } + | LATENCY_LOG EQUAL NUMBER { default_core_cfg.latency_log=$3; } + | LATENCY_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; } + | LATENCY_LIMIT_ACTION EQUAL error { yyerror("number expected"); } | UDP_MTU EQUAL NUMBER { default_core_cfg.udp_mtu=$3; } | UDP_MTU EQUAL error { yyerror("number expected"); } | FORCE_RPORT EQUAL NUMBER diff --git a/cfg_core.c b/cfg_core.c index 27a55b3..87af945 100644 --- a/cfg_core.c +++ b/cfg_core.c @@ -121,7 +121,10 @@ struct cfg_group_core default_core_cfg = { L_DBG, /*!< memlog */ 3, /*!< mem_summary -flags: 0 off, 1 pkg_status, 2 shm_status, 4 pkg_sums, 8 shm_sums, 16 short_status */ - L_ERR /*!< corelog */ + L_ERR, /*!< corelog */ + L_ERR, /*!< latency log */ + 0, /*!< latency limit db */ + 0 /*!< latency limit action */ };
void *core_cfg = &default_core_cfg; @@ -311,5 +314,11 @@ cfg_def_t core_cfg_def[] = { " 16 - short status instead of dump" }, {"corelog", CFG_VAR_INT|CFG_ATOMIC, 0, 0, 0, 0, "log level for non-critical core error messages"}, + {"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, + "limit is ms for alerting on time consuming db commands"}, + {"latency_limit_action", CFG_VAR_INT|CFG_ATOMIC, 0, 0, 0, 0, + "limit is ms for alerting on time consuming config actions"}, {0, 0, 0, 0, 0, 0} }; diff --git a/cfg_core.h b/cfg_core.h index 25f69ae..c5c4250 100644 --- a/cfg_core.h +++ b/cfg_core.h @@ -109,6 +109,9 @@ struct cfg_group_core { int memlog; /*!< log level for memory status/summary info */ int mem_summary; /*!< display memory status/summary info on exit */ int corelog; /*!< log level for non-critcal core error messages */ + 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 */ };
extern struct cfg_group_core default_core_cfg; diff --git a/lib/srdb1/db_query.c b/lib/srdb1/db_query.c index 3f75421..99079dc 100644 --- a/lib/srdb1/db_query.c +++ b/lib/srdb1/db_query.c @@ -38,10 +38,34 @@ #include "db_ut.h" #include "db_query.h" #include "../../globals.h" +#include "../../timer.h"
static str sql_str; static char *sql_buf = NULL;
+static inline int db_do_submit_query(const db1_con_t* _h, const str *_query, + int (*submit_query)(const db1_con_t*, const str*)) +{ + int ret; + unsigned int ms; + + if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) + ms = TICKS_TO_MS(get_ticks_raw()); + + ret = submit_query(_h, _query); + + if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) { + ms = TICKS_TO_MS(get_ticks_raw()) - ms; + if(ms >= cfg_get(core, core_cfg, latency_limit_action)) { + LOG(cfg_get(core, core_cfg, latency_log), + "alert - query execution too long [%u ms] for [%.*s]\n", + ms, _query->len<50?_query->len:50, _query->s); + } + } + + return ret; +} + int db_do_query(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _op, const db_val_t* _v, const db_key_t* _c, const int _n, const int _nc, 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, sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) { + if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; } @@ -128,7 +152,7 @@ int db_do_raw_query(const db1_con_t* _h, const str* _s, db1_res_t** _r, return -1; }
- if (submit_query(_h, _s) < 0) { + if (db_do_submit_query(_h, _s, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; } @@ -182,7 +206,7 @@ int db_do_insert_cmd(const db1_con_t* _h, const db_key_t* _k, const db_val_t* _v sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) { + if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; } @@ -238,7 +262,7 @@ int db_do_delete(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _o, sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) { + if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; } @@ -284,7 +308,7 @@ int db_do_update(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _o, sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) { + if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; } @@ -330,7 +354,7 @@ int db_do_replace(const db1_con_t* _h, const db_key_t* _k, const db_val_t* _v, sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) { + if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; } diff --git a/route_struct.h b/route_struct.h index 4bb5045..b176b9c 100644 --- a/route_struct.h +++ b/route_struct.h @@ -119,6 +119,9 @@ enum action_type{ CFG_SELECT_T, CFG_RESET_T }; + +#define is_mod_func(a) ((a)->type>=MODULE0_T && (a)->type<=MODULEX_RVE_T) + /* parameter types for actions or types for expression right operands (WARNING right operands only, not working for left operands) */ enum _operand_subtype{
Nice!
2012/3/26 Daniel-Constantin Mierla miconda@gmail.com:
Module: sip-router Branch: master Commit: 930aba2973c19370a5d50aac2661be66e9aacbc3 URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=930aba29...
Author: Daniel-Constantin Mierla miconda@gmail.com Committer: Daniel-Constantin Mierla miconda@gmail.com Date: Sun Mar 25 13:39:20 2012 +0200
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
action.c | 15 +++++++++++++++ cfg.lex | 7 +++++++ cfg.y | 9 +++++++++ cfg_core.c | 11 ++++++++++- cfg_core.h | 3 +++ lib/srdb1/db_query.c | 36 ++++++++++++++++++++++++++++++------ route_struct.h | 3 +++ 7 files changed, 77 insertions(+), 7 deletions(-)
diff --git a/action.c b/action.c index e044f65..6178dd7 100644 --- a/action.c +++ b/action.c @@ -1580,6 +1580,7 @@ int run_actions(struct run_act_ctx* h, struct action* a, struct sip_msg* msg) struct action* t; int ret; struct sr_module *mod;
- unsigned int ms;
ret=E_UNSPEC; h->rec_lev++; @@ -1609,7 +1610,21 @@ int run_actions(struct run_act_ctx* h, struct action* a, struct sip_msg* msg) }
for (t=a; t!=0; t=t->next){
- if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0))
- ms = TICKS_TO_MS(get_ticks_raw());
ret=do_action(h, t, msg);
- if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) {
- ms = TICKS_TO_MS(get_ticks_raw()) - ms;
- if(ms >= cfg_get(core, core_cfg, latency_limit_action)) {
- LOG(cfg_get(core, core_cfg, latency_log),
- "alert - action [%s (%d)]"
- " cfg [%s:%d] took too long [%u ms]\n",
- is_mod_func(t) ?
- ((cmd_export_common_t*)(t->val[0].u.data))->name
- : "corefunc",
- t->type, (t->cfile)?t->cfile:"", t->cline, ms);
- }
- }
/* break, return or drop/exit stop execution of the current block */ if (unlikely(h->run_flags & (BREAK_R_F|RETURN_R_F|EXIT_R_F))){ diff --git a/cfg.lex b/cfg.lex index 00a55e0..2d1494b 100644 --- a/cfg.lex +++ b/cfg.lex @@ -503,6 +503,10 @@ STUN_ALLOW_FP "stun_allow_fp"
SERVER_ID "server_id"
+LATENCY_LOG latency_log +LATENCY_LIMIT_DB latency_limit_db +LATENCY_LIMIT_ACTION latency_limit_action
CFG_DESCRIPTION "description"|"descr"|"desc"
LOADMODULE loadmodule @@ -965,6 +969,9 @@ IMPORTFILE "import_file" <INITIAL>{HTTP_REPLY_HACK} { count(); yylval.strval=yytext; return HTTP_REPLY_HACK; } <INITIAL>{SERVER_ID} { count(); yylval.strval=yytext; return SERVER_ID;} +<INITIAL>{LATENCY_LOG} { count(); yylval.strval=yytext; return LATENCY_LOG;} +<INITIAL>{LATENCY_LIMIT_DB} { count(); yylval.strval=yytext; return LATENCY_LIMIT_DB;} +<INITIAL>{LATENCY_LIMIT_ACTION} { count(); yylval.strval=yytext; return LATENCY_LIMIT_ACTION;} <INITIAL>{CFG_DESCRIPTION} { count(); yylval.strval=yytext; return CFG_DESCRIPTION; } <INITIAL>{LOADMODULE} { count(); yylval.strval=yytext; return LOADMODULE; } <INITIAL>{LOADPATH} { count(); yylval.strval=yytext; return LOADPATH; } diff --git a/cfg.y b/cfg.y index 9edd0fde..274e1e8 100644 --- a/cfg.y +++ b/cfg.y @@ -559,6 +559,9 @@ extern char *finame; %token HTTP_REPLY_HACK %token CFG_DESCRIPTION %token SERVER_ID +%token LATENCY_LOG +%token LATENCY_LIMIT_DB +%token LATENCY_LIMIT_ACTION
%token FLAGS_DECL %token AVPFLAGS_DECL @@ -1671,6 +1674,12 @@ assign_stm: | STUN_ALLOW_FP EQUAL NUMBER { IF_STUN(stun_allow_fp=$3) ; } | STUN_ALLOW_FP EQUAL error{ yyerror("number expected"); } | SERVER_ID EQUAL NUMBER { server_id=$3; }
- | LATENCY_LOG EQUAL NUMBER { default_core_cfg.latency_log=$3; }
- | LATENCY_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; }
- | LATENCY_LIMIT_ACTION EQUAL error { yyerror("number expected"); }
| UDP_MTU EQUAL NUMBER { default_core_cfg.udp_mtu=$3; } | UDP_MTU EQUAL error { yyerror("number expected"); } | FORCE_RPORT EQUAL NUMBER diff --git a/cfg_core.c b/cfg_core.c index 27a55b3..87af945 100644 --- a/cfg_core.c +++ b/cfg_core.c @@ -121,7 +121,10 @@ struct cfg_group_core default_core_cfg = { L_DBG, /*!< memlog */ 3, /*!< mem_summary -flags: 0 off, 1 pkg_status, 2 shm_status, 4 pkg_sums, 8 shm_sums, 16 short_status */
- L_ERR /*!< corelog */
- L_ERR, /*!< corelog */
- L_ERR, /*!< latency log */
- 0, /*!< latency limit db */
- 0 /*!< latency limit action */
};
void *core_cfg = &default_core_cfg; @@ -311,5 +314,11 @@ cfg_def_t core_cfg_def[] = { " 16 - short status instead of dump" }, {"corelog", CFG_VAR_INT|CFG_ATOMIC, 0, 0, 0, 0, "log level for non-critical core error messages"},
- {"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,
- "limit is ms for alerting on time consuming db commands"},
- {"latency_limit_action", CFG_VAR_INT|CFG_ATOMIC, 0, 0, 0, 0,
- "limit is ms for alerting on time consuming config actions"},
{0, 0, 0, 0, 0, 0} }; diff --git a/cfg_core.h b/cfg_core.h index 25f69ae..c5c4250 100644 --- a/cfg_core.h +++ b/cfg_core.h @@ -109,6 +109,9 @@ struct cfg_group_core { int memlog; /*!< log level for memory status/summary info */ int mem_summary; /*!< display memory status/summary info on exit */ int corelog; /*!< log level for non-critcal core error messages */
- 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 */
};
extern struct cfg_group_core default_core_cfg; diff --git a/lib/srdb1/db_query.c b/lib/srdb1/db_query.c index 3f75421..99079dc 100644 --- a/lib/srdb1/db_query.c +++ b/lib/srdb1/db_query.c @@ -38,10 +38,34 @@ #include "db_ut.h" #include "db_query.h" #include "../../globals.h" +#include "../../timer.h"
static str sql_str; static char *sql_buf = NULL;
+static inline int db_do_submit_query(const db1_con_t* _h, const str *_query,
- int (*submit_query)(const db1_con_t*, const str*))
+{
- int ret;
- unsigned int ms;
- if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0))
- ms = TICKS_TO_MS(get_ticks_raw());
- ret = submit_query(_h, _query);
- if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) {
- ms = TICKS_TO_MS(get_ticks_raw()) - ms;
- if(ms >= cfg_get(core, core_cfg, latency_limit_action)) {
- LOG(cfg_get(core, core_cfg, latency_log),
- "alert - query execution too long [%u ms] for [%.*s]\n",
- ms, _query->len<50?_query->len:50, _query->s);
- }
- }
- return ret;
+}
int db_do_query(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _op, const db_val_t* _v, const db_key_t* _c, const int _n, const int _nc, 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, sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) {
- if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
LM_ERR("error while submitting query\n"); return -2; } @@ -128,7 +152,7 @@ int db_do_raw_query(const db1_con_t* _h, const str* _s, db1_res_t** _r, return -1; }
- if (submit_query(_h, _s) < 0) {
- if (db_do_submit_query(_h, _s, submit_query) < 0) {
LM_ERR("error while submitting query\n"); return -2; } @@ -182,7 +206,7 @@ int db_do_insert_cmd(const db1_con_t* _h, const db_key_t* _k, const db_val_t* _v sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) {
- if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
LM_ERR("error while submitting query\n"); return -2; } @@ -238,7 +262,7 @@ int db_do_delete(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _o, sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) {
- if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
LM_ERR("error while submitting query\n"); return -2; } @@ -284,7 +308,7 @@ int db_do_update(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _o, sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) {
- if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
LM_ERR("error while submitting query\n"); return -2; } @@ -330,7 +354,7 @@ int db_do_replace(const db1_con_t* _h, const db_key_t* _k, const db_val_t* _v, sql_str.s = sql_buf; sql_str.len = off;
- if (submit_query(_h, &sql_str) < 0) {
- if (db_do_submit_query(_h, &sql_str, submit_query) < 0) {
LM_ERR("error while submitting query\n"); return -2; } diff --git a/route_struct.h b/route_struct.h index 4bb5045..b176b9c 100644 --- a/route_struct.h +++ b/route_struct.h @@ -119,6 +119,9 @@ enum action_type{ CFG_SELECT_T, CFG_RESET_T };
+#define is_mod_func(a) ((a)->type>=MODULE0_T && (a)->type<=MODULEX_RVE_T)
/* parameter types for actions or types for expression right operands (WARNING right operands only, not working for left operands) */ enum _operand_subtype{
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
26 mar 2012 kl. 10:17 skrev Carsten Bock:
Nice!
+pi
/O :-)
2012/3/26 Daniel-Constantin Mierla miconda@gmail.com:
Module: sip-router Branch: master Commit: 930aba2973c19370a5d50aac2661be66e9aacbc3 URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=930aba29...
Author: Daniel-Constantin Mierla miconda@gmail.com Committer: Daniel-Constantin Mierla miconda@gmail.com Date: Sun Mar 25 13:39:20 2012 +0200
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
action.c | 15 +++++++++++++++ cfg.lex | 7 +++++++ cfg.y | 9 +++++++++ cfg_core.c | 11 ++++++++++- cfg_core.h | 3 +++ lib/srdb1/db_query.c | 36 ++++++++++++++++++++++++++++++------ route_struct.h | 3 +++ 7 files changed, 77 insertions(+), 7 deletions(-)
diff --git a/action.c b/action.c index e044f65..6178dd7 100644 --- a/action.c +++ b/action.c @@ -1580,6 +1580,7 @@ int run_actions(struct run_act_ctx* h, struct action* a, struct sip_msg* msg) struct action* t; int ret; struct sr_module *mod;
unsigned int ms; ret=E_UNSPEC; h->rec_lev++;@@ -1609,7 +1610,21 @@ int run_actions(struct run_act_ctx* h, struct action* a, struct sip_msg* msg) }
for (t=a; t!=0; t=t->next){
if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0))ms = TICKS_TO_MS(get_ticks_raw()); ret=do_action(h, t, msg);if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) {ms = TICKS_TO_MS(get_ticks_raw()) - ms;if(ms >= cfg_get(core, core_cfg, latency_limit_action)) {LOG(cfg_get(core, core_cfg, latency_log),"alert - action [%s (%d)]"" cfg [%s:%d] took too long [%u ms]\n",is_mod_func(t) ?((cmd_export_common_t*)(t->val[0].u.data))->name: "corefunc",t->type, (t->cfile)?t->cfile:"", t->cline, ms);}} /* break, return or drop/exit stop execution of the current block */ if (unlikely(h->run_flags & (BREAK_R_F|RETURN_R_F|EXIT_R_F))){diff --git a/cfg.lex b/cfg.lex index 00a55e0..2d1494b 100644 --- a/cfg.lex +++ b/cfg.lex @@ -503,6 +503,10 @@ STUN_ALLOW_FP "stun_allow_fp"
SERVER_ID "server_id"
+LATENCY_LOG latency_log +LATENCY_LIMIT_DB latency_limit_db +LATENCY_LIMIT_ACTION latency_limit_action
CFG_DESCRIPTION "description"|"descr"|"desc"
LOADMODULE loadmodule @@ -965,6 +969,9 @@ IMPORTFILE "import_file" <INITIAL>{HTTP_REPLY_HACK} { count(); yylval.strval=yytext; return HTTP_REPLY_HACK; } <INITIAL>{SERVER_ID} { count(); yylval.strval=yytext; return SERVER_ID;} +<INITIAL>{LATENCY_LOG} { count(); yylval.strval=yytext; return LATENCY_LOG;} +<INITIAL>{LATENCY_LIMIT_DB} { count(); yylval.strval=yytext; return LATENCY_LIMIT_DB;} +<INITIAL>{LATENCY_LIMIT_ACTION} { count(); yylval.strval=yytext; return LATENCY_LIMIT_ACTION;} <INITIAL>{CFG_DESCRIPTION} { count(); yylval.strval=yytext; return CFG_DESCRIPTION; } <INITIAL>{LOADMODULE} { count(); yylval.strval=yytext; return LOADMODULE; } <INITIAL>{LOADPATH} { count(); yylval.strval=yytext; return LOADPATH; } diff --git a/cfg.y b/cfg.y index 9edd0fde..274e1e8 100644 --- a/cfg.y +++ b/cfg.y @@ -559,6 +559,9 @@ extern char *finame; %token HTTP_REPLY_HACK %token CFG_DESCRIPTION %token SERVER_ID +%token LATENCY_LOG +%token LATENCY_LIMIT_DB +%token LATENCY_LIMIT_ACTION
%token FLAGS_DECL %token AVPFLAGS_DECL @@ -1671,6 +1674,12 @@ assign_stm: | STUN_ALLOW_FP EQUAL NUMBER { IF_STUN(stun_allow_fp=$3) ; } | STUN_ALLOW_FP EQUAL error{ yyerror("number expected"); } | SERVER_ID EQUAL NUMBER { server_id=$3; }
- | LATENCY_LOG EQUAL NUMBER { default_core_cfg.latency_log=$3; }
| LATENCY_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; }
| LATENCY_LIMIT_ACTION EQUAL error { yyerror("number expected"); } | UDP_MTU EQUAL NUMBER { default_core_cfg.udp_mtu=$3; } | UDP_MTU EQUAL error { yyerror("number expected"); } | FORCE_RPORT EQUAL NUMBERdiff --git a/cfg_core.c b/cfg_core.c index 27a55b3..87af945 100644 --- a/cfg_core.c +++ b/cfg_core.c @@ -121,7 +121,10 @@ struct cfg_group_core default_core_cfg = { L_DBG, /*!< memlog */ 3, /*!< mem_summary -flags: 0 off, 1 pkg_status, 2 shm_status, 4 pkg_sums, 8 shm_sums, 16 short_status */
L_ERR /*!< corelog */
L_ERR, /*!< corelog */L_ERR, /*!< latency log */0, /*!< latency limit db */0 /*!< latency limit action */};
void *core_cfg = &default_core_cfg; @@ -311,5 +314,11 @@ cfg_def_t core_cfg_def[] = { " 16 - short status instead of dump" }, {"corelog", CFG_VAR_INT|CFG_ATOMIC, 0, 0, 0, 0, "log level for non-critical core error messages"},
{"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,"limit is ms for alerting on time consuming db commands"},{"latency_limit_action", CFG_VAR_INT|CFG_ATOMIC, 0, 0, 0, 0,"limit is ms for alerting on time consuming config actions"}, {0, 0, 0, 0, 0, 0}}; diff --git a/cfg_core.h b/cfg_core.h index 25f69ae..c5c4250 100644 --- a/cfg_core.h +++ b/cfg_core.h @@ -109,6 +109,9 @@ struct cfg_group_core { int memlog; /*!< log level for memory status/summary info */ int mem_summary; /*!< display memory status/summary info on exit */ int corelog; /*!< log level for non-critcal core error messages */
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 */};
extern struct cfg_group_core default_core_cfg; diff --git a/lib/srdb1/db_query.c b/lib/srdb1/db_query.c index 3f75421..99079dc 100644 --- a/lib/srdb1/db_query.c +++ b/lib/srdb1/db_query.c @@ -38,10 +38,34 @@ #include "db_ut.h" #include "db_query.h" #include "../../globals.h" +#include "../../timer.h"
static str sql_str; static char *sql_buf = NULL;
+static inline int db_do_submit_query(const db1_con_t* _h, const str *_query,
int (*submit_query)(const db1_con_t*, const str*))+{
int ret;unsigned int ms;if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0))ms = TICKS_TO_MS(get_ticks_raw());ret = submit_query(_h, _query);if(unlikely(cfg_get(core, core_cfg, latency_limit_action)>0)) {ms = TICKS_TO_MS(get_ticks_raw()) - ms;if(ms >= cfg_get(core, core_cfg, latency_limit_action)) {LOG(cfg_get(core, core_cfg, latency_log),"alert - query execution too long [%u ms] for [%.*s]\n",ms, _query->len<50?_query->len:50, _query->s);}}return ret;+}
int db_do_query(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _op, const db_val_t* _v, const db_key_t* _c, const int _n, const int _nc, 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, sql_str.s = sql_buf; sql_str.len = off;
if (submit_query(_h, &sql_str) < 0) {
if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; }@@ -128,7 +152,7 @@ int db_do_raw_query(const db1_con_t* _h, const str* _s, db1_res_t** _r, return -1; }
if (submit_query(_h, _s) < 0) {
if (db_do_submit_query(_h, _s, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; }@@ -182,7 +206,7 @@ int db_do_insert_cmd(const db1_con_t* _h, const db_key_t* _k, const db_val_t* _v sql_str.s = sql_buf; sql_str.len = off;
if (submit_query(_h, &sql_str) < 0) {
if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; }@@ -238,7 +262,7 @@ int db_do_delete(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _o, sql_str.s = sql_buf; sql_str.len = off;
if (submit_query(_h, &sql_str) < 0) {
if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; }@@ -284,7 +308,7 @@ int db_do_update(const db1_con_t* _h, const db_key_t* _k, const db_op_t* _o, sql_str.s = sql_buf; sql_str.len = off;
if (submit_query(_h, &sql_str) < 0) {
if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; }@@ -330,7 +354,7 @@ int db_do_replace(const db1_con_t* _h, const db_key_t* _k, const db_val_t* _v, sql_str.s = sql_buf; sql_str.len = off;
if (submit_query(_h, &sql_str) < 0) {
if (db_do_submit_query(_h, &sql_str, submit_query) < 0) { LM_ERR("error while submitting query\n"); return -2; }diff --git a/route_struct.h b/route_struct.h index 4bb5045..b176b9c 100644 --- a/route_struct.h +++ b/route_struct.h @@ -119,6 +119,9 @@ enum action_type{ CFG_SELECT_T, CFG_RESET_T };
+#define is_mod_func(a) ((a)->type>=MODULE0_T && (a)->type<=MODULEX_RVE_T)
/* parameter types for actions or types for expression right operands (WARNING right operands only, not working for left operands) */ enum _operand_subtype{
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
-- Carsten Bock CEO (Geschäftsführer)
ng-voice GmbH Schomburgstr. 80 D-22767 Hamburg / Germany
http://www.ng-voice.com mailto:carsten@ng-voice.com
Mobile +49 179 2021244 Office +49 40 34927219 Fax +49 40 34927220
Sitz der Gesellschaft: Hamburg Registergericht: Amtsgericht Hamburg, HRB 120189 Geschäftsführer: Carsten Bock Ust-ID: DE279344284
Hier finden Sie unsere handelsrechtlichen Pflichtangaben: http://www.ng-voice.com/imprint/
-- Meet ng-voice at LinuxTag 2012 in Berlin - May 23rd - 26th, 2012. Save the date!
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
--- * Olle E Johansson - oej@edvina.net * Cell phone +46 70 593 68 51, Office +46 8 96 40 20, Sweden
On 26.03.2012 09:54, Daniel-Constantin Mierla wrote:
Module: sip-router Branch: master Commit: 930aba2973c19370a5d50aac2661be66e9aacbc3 URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=930aba29...
Author: Daniel-Constantin Mierlamiconda@gmail.com Committer: Daniel-Constantin Mierlamiconda@gmail.com Date: Sun Mar 25 13:39:20 2012 +0200
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
Why not the whole query? Would help debugging.
Klaus
On 3/26/12 4:27 PM, Klaus Darilion wrote:
On 26.03.2012 09:54, Daniel-Constantin Mierla wrote:
Module: sip-router Branch: master Commit: 930aba2973c19370a5d50aac2661be66e9aacbc3 URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=930aba29...
Author: Daniel-Constantin Mierlamiconda@gmail.com Committer: Daniel-Constantin Mierlamiconda@gmail.com Date: Sun Mar 25 13:39:20 2012 +0200
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
Why not the whole query? Would help debugging.
For some queries, it will be quite long, e.g., presence queries with xml docs. The purpose was to identify the query, the length can be adjusted in the log command very easy in the code if people prefer longer output.
Cheers, Daniel
Daniel-Constantin Mierla writes:
- 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,
thanks for implementing these. looks like they are not yet in core cookbook.
-- juha
Hello,
On 3/28/12 6:39 PM, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
- 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,
thanks for implementing these. looks like they are not yet in core cookbook.
should be now, along with the other new parameters I added lately.
Cheers, Daniel
-
Carsten Bock -
Daniel-Constantin Mierla -
Juha Heinanen -
Klaus Darilion -
Olle E. Johansson