[sr-dev] git:master: core: new parameters to control and alert on time consuming ops
Olle E. Johansson
oej at edvina.net
Mon Mar 26 10:21:30 CEST 2012
26 mar 2012 kl. 10:17 skrev Carsten Bock:
> Nice!
+pi
/O :-)
>
> 2012/3/26 Daniel-Constantin Mierla <miconda at gmail.com>:
>> Module: sip-router
>> Branch: master
>> Commit: 930aba2973c19370a5d50aac2661be66e9aacbc3
>> URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=930aba2973c19370a5d50aac2661be66e9aacbc3
>>
>> Author: Daniel-Constantin Mierla <miconda at gmail.com>
>> Committer: Daniel-Constantin Mierla <miconda at 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 at 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 at 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 at lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
---
* Olle E Johansson - oej at edvina.net
* Cell phone +46 70 593 68 51, Office +46 8 96 40 20, Sweden
More information about the sr-dev
mailing list