core: new parameters to control and alert on time consuming ops
authorDaniel-Constantin Mierla <miconda@gmail.com>
Sun, 25 Mar 2012 11:39:20 +0000 (13:39 +0200)
committerDaniel-Constantin Mierla <miconda@gmail.com>
Sun, 25 Mar 2012 11:39:20 +0000 (13:39 +0200)
- 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
cfg.lex
cfg.y
cfg_core.c
cfg_core.h
lib/srdb1/db_query.c
route_struct.h

index e044f65..6178dd7 100644 (file)
--- 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 (file)
--- 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 9edd0fd..274e1e8 100644 (file)
--- 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 
index 27a55b3..87af945 100644 (file)
@@ -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}
 };
index 25f69ae..c5c4250 100644 (file)
@@ -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;
index 3f75421..99079dc 100644 (file)
 #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;
        }
index 4bb5045..b176b9c 100644 (file)
@@ -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{