core: new core parameter latency_cfg_log
authorDaniel-Constantin Mierla <miconda@gmail.com>
Mon, 25 Apr 2016 14:57:19 +0000 (16:57 +0200)
committerDaniel-Constantin Mierla <miconda@gmail.com>
Mon, 25 Apr 2016 14:57:19 +0000 (16:57 +0200)
- if set to a log level less or equal than debug parameter, a log
  message with the duration of executing request route or reply route is
  printed to syslog
- default value is L_DBG

cfg.lex
cfg.y
cfg_core.c
cfg_core.h
receive.c

diff --git a/cfg.lex b/cfg.lex
index 336322c..9410506 100644 (file)
--- a/cfg.lex
+++ b/cfg.lex
@@ -440,6 +440,7 @@ SERVER_ID     "server_id"
 MAX_RECURSIVE_LEVEL            "max_recursive_level"
 MAX_BRANCHES_PARAM             "max_branches"|"max_branches"
 
+LATENCY_CFG_LOG                        latency_cfg_log
 LATENCY_LOG                            latency_log
 LATENCY_LIMIT_DB               latency_limit_db
 LATENCY_LIMIT_ACTION   latency_limit_action
@@ -910,6 +911,7 @@ IMPORTFILE      "import_file"
 <INITIAL>{MAX_RECURSIVE_LEVEL}  { count(); yylval.strval=yytext; return MAX_RECURSIVE_LEVEL;}
 <INITIAL>{MAX_BRANCHES_PARAM}  { count(); yylval.strval=yytext; return MAX_BRANCHES_PARAM;}
 <INITIAL>{LATENCY_LOG}  { count(); yylval.strval=yytext; return LATENCY_LOG;}
+<INITIAL>{LATENCY_CFG_LOG}  { count(); yylval.strval=yytext; return LATENCY_CFG_LOG;}
 <INITIAL>{MSG_TIME}  { count(); yylval.strval=yytext; return MSG_TIME;}
 <INITIAL>{ONSEND_RT_REPLY}     { count(); yylval.strval=yytext; return ONSEND_RT_REPLY; }
 <INITIAL>{LATENCY_LIMIT_DB}  { count(); yylval.strval=yytext; return LATENCY_LIMIT_DB;}
diff --git a/cfg.y b/cfg.y
index 55d4220..91553ff 100644 (file)
--- a/cfg.y
+++ b/cfg.y
@@ -476,6 +476,7 @@ extern char *default_routename;
 %token SERVER_ID
 %token MAX_RECURSIVE_LEVEL
 %token MAX_BRANCHES_PARAM
+%token LATENCY_CFG_LOG
 %token LATENCY_LOG
 %token LATENCY_LIMIT_DB
 %token LATENCY_LIMIT_ACTION
@@ -1521,6 +1522,8 @@ assign_stm:
     | MAX_BRANCHES_PARAM EQUAL NUMBER { sr_dst_max_branches = $3; }
     | LATENCY_LOG EQUAL NUMBER { default_core_cfg.latency_log=$3; }
        | LATENCY_LOG EQUAL error  { yyerror("number  expected"); }
+    | LATENCY_CFG_LOG EQUAL NUMBER { default_core_cfg.latency_cfg_log=$3; }
+       | LATENCY_CFG_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; }
@@ -1531,7 +1534,7 @@ assign_stm:
        | ONSEND_RT_REPLY EQUAL error { yyerror("int value expected"); }
        | UDP_MTU EQUAL NUMBER { default_core_cfg.udp_mtu=$3; }
        | UDP_MTU EQUAL error { yyerror("number expected"); }
-       | FORCE_RPORT EQUAL NUMBER 
+       | FORCE_RPORT EQUAL NUMBER
                { default_core_cfg.force_rport=$3; fix_global_req_flags(0, 0); }
        | FORCE_RPORT EQUAL error { yyerror("boolean value expected"); }
        | UDP_MTU_TRY_PROTO EQUAL proto
index 98a9c01..4f23f8a 100644 (file)
@@ -116,6 +116,7 @@ struct cfg_group_core default_core_cfg = {
        0, /*!< mem_safety - 0 disabled */
        0, /*!< mem_join - 0 disabled */
        L_ERR, /*!< corelog */
+       L_DBG, /*!< latency cfg log */
        L_ERR, /*!< latency log */
        0, /*!< latency limit db */
        0 /*!< latency limit action */
@@ -128,7 +129,7 @@ static int check_raw_sock_support(void* cfg_h, str* gname, str* name,
                                                                        void** v)
 {
        int val;
-       
+
        val = (int)(long)(*v);
 #ifndef USE_RAW_SOCKS
        if (val > 0) {
@@ -314,6 +315,8 @@ cfg_def_t core_cfg_def[] = {
                "join free memory fragments"},
        {"corelog",             CFG_VAR_INT|CFG_ATOMIC, 0, 0, 0, 0,
                "log level for non-critical core error messages"},
+       {"latency_cfg_log",             CFG_VAR_INT|CFG_ATOMIC, 0, 0, 0, 0,
+               "log level for printing latency of routing blocks"},
        {"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,
index f7db8d0..9c10b55 100644 (file)
@@ -104,6 +104,7 @@ struct cfg_group_core {
        int mem_safety; /*!< memory safety control option */
        int mem_join; /*!< memory free fragments join option */
        int corelog; /*!< log level for non-critcal core error messages */
+       int latency_cfg_log; /*!< log level for printing latency of routing blocks */
        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 */
index 03f809d..b94b921 100644 (file)
--- a/receive.c
+++ b/receive.c
@@ -121,10 +121,13 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
        int ret;
 #ifdef STATS
        int skipped = 1;
+       int stats_on = 1;
+#else
+       int stats_on = 0;
+#endif
        struct timeval tvb, tve;
        struct timezone tz;
-       unsigned int diff;
-#endif
+       unsigned int diff = 0;
        str inb;
        sr_net_info_t netinfo;
        sr_kemi_eng_t *keng = NULL;
@@ -222,9 +225,10 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
 
        /*      skip: */
                LM_DBG("preparing to run routing scripts...\n");
-#ifdef  STATS
-               gettimeofday( & tvb, &tz );
-#endif
+               if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
+                               || stats_on==1) {
+                       gettimeofday( & tvb, &tz );
+               }
                /* execute pre-script callbacks, if any; -jiri */
                /* if some of the callbacks said not to continue with
                 * script processing, don't do so
@@ -256,14 +260,18 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
                        }
                }
 
+               if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
+                               || stats_on==1) {
+                       gettimeofday( & tve, &tz );
+                       diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
+                       LOG(cfg_get(core, core_cfg, latency_cfg_log),
+                                       "request-route executed in: %d usec\n", diff);
 #ifdef STATS
-               gettimeofday( & tve, &tz );
-               diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
-               stats->processed_requests++;
-               stats->acc_req_time += diff;
-               LM_DBG("successfully ran routing scripts...(%d usec)\n", diff);
-               STATS_RX_REQUEST( msg->first_line.u.request.method_value );
+                       stats->processed_requests++;
+                       stats->acc_req_time += diff;
+                       STATS_RX_REQUEST( msg->first_line.u.request.method_value );
 #endif
+               }
 
                /* execute post request-script callbacks */
                exec_post_script_cb(msg, REQUEST_CB_TYPE);
@@ -276,8 +284,11 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
                        goto error02;
                }
 
+               if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
+                               || stats_on==1) {
+                       gettimeofday( & tvb, &tz );
+               }
 #ifdef STATS
-               gettimeofday( & tvb, &tz );
                STATS_RX_RESPONSE ( msg->first_line.u.reply.statuscode / 100 );
 #endif
 
@@ -322,13 +333,17 @@ int receive_msg(char* buf, unsigned int len, struct receive_info* rcv_info)
                /* send the msg */
                forward_reply(msg);
        skip_send_reply:
+               if(is_printable(cfg_get(core, core_cfg, latency_cfg_log))
+                               || stats_on==1) {
+                       gettimeofday( & tve, &tz );
+                       diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
+                       LOG(cfg_get(core, core_cfg, latency_cfg_log),
+                                       "reply-route executed in: %d usec\n", diff);
 #ifdef STATS
-               gettimeofday( & tve, &tz );
-               diff = (tve.tv_sec-tvb.tv_sec)*1000000+(tve.tv_usec-tvb.tv_usec);
-               stats->processed_responses++;
-               stats->acc_res_time+=diff;
-               LM_DBG("successfully ran reply processing...(%d usec)\n", diff);
+                       stats->processed_responses++;
+                       stats->acc_res_time+=diff;
 #endif
+               }
 
                /* execute post reply-script callbacks */
                exec_post_script_cb(msg, ONREPLY_CB_TYPE);