Re: [sr-dev] git:master: core: new parameters to control and alert on time consuming ops

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 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

-- 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