/* * $Id: benchmark.c 941 2007-04-11 12:37:21Z bastian $ * * Benchmarking module for Kamailio * * Copyright (C) 2007 Collax GmbH * (Bastian Friedrich ) * Copyright (C) 2007 Voice Sistem SRL * * This file is part of Kamailio, a free SIP server. * * Kamailio is free software; you can redistribute it and/or modify * it under the terms of the GNU General Public License as published by * the Free Software Foundation; either version 2 of the License, or * (at your option) any later version * * Kamailio is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * GNU General Public License for more details. * * You should have received a copy of the GNU General Public License * along with this program; if not, write to the Free Software * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA * */ /*! \file * \brief Benchmark :: Module Core * * \ingroup benchmark * - Module: benchmark */ /*! \defgroup benchmark Benchmark :: Developer benchmarking module * * This module is for Kamailio developers, as well as admins. It gives * a possibility to clock certain critical paths in module code or * configuration sections. * */ #define _GNU_SOURCE #include #include #include #include "../../sr_module.h" #include "../../lib/kmi/mi.h" #include "../../mem/mem.h" #include "../../ut.h" #include "benchmark.h" #include "../../mem/shm_mem.h" MODULE_VERSION /* Exported functions */ int bm_start_timer(struct sip_msg* _msg, char* timer, char *foobar); int bm_log_timer(struct sip_msg* _msg, char* timer, char* mystr); /* * Module destroy function prototype */ static void destroy(void); /* * Module initialization function prototype */ static int mod_init(void); /* * Exported parameters * Copied to mycfg on module initialization */ static int bm_enable_global = 0; static int bm_granularity = 1; static int bm_loglevel = L_INFO; static int _bm_last_time_diff = 0; /* * Module setup */ typedef struct bm_cfg { int enable_global; int granularity; int loglevel; /* The internal timers */ int nrtimers; benchmark_timer_t *timers; benchmark_timer_t **tindex; } bm_cfg_t; /* * The setup is located in shared memory so that * all instances can access this variable */ bm_cfg_t *bm_mycfg = 0; static inline int fixup_bm_timer(void** param, int param_no); /* * Exported functions */ static cmd_export_t cmds[] = { { "bm_start_timer", (cmd_function)bm_start_timer, 1, fixup_bm_timer, 0, REQUEST_ROUTE|FAILURE_ROUTE|ONREPLY_ROUTE|BRANCH_ROUTE|LOCAL_ROUTE }, { "bm_log_timer", (cmd_function)bm_log_timer, 1, fixup_bm_timer, 0, REQUEST_ROUTE|FAILURE_ROUTE|ONREPLY_ROUTE|BRANCH_ROUTE|LOCAL_ROUTE }, {"load_bm", (cmd_function)load_bm, 0, 0, 0, 0}, { 0, 0, 0, 0, 0, 0 } }; /* * Exported parameters */ static param_export_t params[] = { {"enable", INT_PARAM, &bm_enable_global}, {"granularity", INT_PARAM, &bm_granularity}, {"loglevel", INT_PARAM, &bm_loglevel}, { 0, 0, 0 } }; /* * Exported MI functions */ struct mi_root* mi_bm_enable_global(struct mi_root *cmd, void *param); struct mi_root* mi_bm_enable_timer(struct mi_root *cmd, void *param); struct mi_root* mi_bm_granularity(struct mi_root *cmd, void *param); struct mi_root* mi_bm_loglevel(struct mi_root *cmd, void *param); static mi_export_t mi_cmds[] = { { "bm_enable_global", mi_bm_enable_global, 0, 0, 0 }, { "bm_enable_timer", mi_bm_enable_timer, 0, 0, 0 }, { "bm_granularity", mi_bm_granularity, 0, 0, 0 }, { "bm_loglevel", mi_bm_loglevel, 0, 0, 0 }, { 0, 0, 0, 0, 0} }; static int bm_get_time_diff(struct sip_msg *msg, pv_param_t *param, pv_value_t *res); static pv_export_t mod_items[] = { { {"BM_time_diff", sizeof("BM_time_diff")-1}, PVT_OTHER, bm_get_time_diff, 0, 0, 0, 0, 0 }, { {0, 0}, 0, 0, 0, 0, 0, 0, 0 } }; /* * Module interface */ struct module_exports exports = { "benchmark", DEFAULT_DLFLAGS, cmds, /* Exported functions */ params, /* Exported parameters */ 0, /* exported statistics */ mi_cmds, /* exported MI functions */ mod_items, /* exported pseudo-variables */ 0, /* extra processes */ mod_init, /* module initialization function */ 0, /* response function */ destroy, /* destroy function */ 0 /* child initialization function */ }; /****************/ /* * mod_init * Called by Kamailio at init time */ static int mod_init(void) { if(register_mi_mod(exports.name, mi_cmds)!=0) { LM_ERR("failed to register MI commands\n"); return -1; } bm_mycfg = (bm_cfg_t*)shm_malloc(sizeof(bm_cfg_t)); memset(bm_mycfg, 0, sizeof(bm_cfg_t)); bm_mycfg->enable_global = bm_enable_global; bm_mycfg->granularity = bm_granularity; bm_mycfg->loglevel = bm_loglevel; return 0; } /* * destroy * called by Kamailio at exit time */ static void destroy(void) { benchmark_timer_t *bmt = 0; benchmark_timer_t *bmp = 0; if(bm_mycfg!=NULL) { /* free timers list */ bmt = bm_mycfg->timers; while(bmt) { bmp = bmt; bmt = bmt->next; shm_free(bmp); } if(bm_mycfg->tindex) shm_free(bm_mycfg->tindex); shm_free(bm_mycfg); } } void bm_reset_timer(int i) { if(bm_mycfg==NULL || bm_mycfg->tindex[i]==NULL) return; bm_mycfg->tindex[i]->calls = 0; bm_mycfg->tindex[i]->sum = 0; bm_mycfg->tindex[i]->last_max = 0; bm_mycfg->tindex[i]->last_min = 0xffffffff; bm_mycfg->tindex[i]->last_sum = 0; bm_mycfg->tindex[i]->global_max = 0; bm_mycfg->tindex[i]->global_min = 0xffffffff; } void reset_timers(void) { int i; if(bm_mycfg==NULL) return; for (i = 0; i < bm_mycfg->nrtimers; i++) bm_reset_timer(i); } /*! \brief * timer_active(). * * Global enable mode can be: * -1 - All timing disabled * 0 - Timing enabled, watch for single timers enabled (default: off) * 1 - Timing enabled for all timers */ static inline int timer_active(unsigned int id) { if (bm_mycfg->enable_global > 0 || bm_mycfg->timers[id].enabled > 0) return 1; else return 0; } /*! \brief * start_timer() */ int _bm_start_timer(unsigned int id) { if (timer_active(id)) { if(bm_get_time(bm_mycfg->tindex[id]->start)!=0) { LM_ERR("error getting current time\n"); return -1; } } return 1; } int bm_start_timer(struct sip_msg* _msg, char* timer, char *foobar) { return _bm_start_timer((unsigned int)(unsigned long)timer); } /*! \brief * log_timer() */ int _bm_log_timer(unsigned int id) { /* BM_CLOCK_REALTIME */ bm_timeval_t now; unsigned long long tdiff; if (!timer_active(id)) return 1; if(bm_get_time(&now)<0) { LM_ERR("error getting current time\n"); return -1; } tdiff = bm_diff_time(bm_mycfg->tindex[id]->start, &now); _bm_last_time_diff = (int)tdiff; /* What to do * - update min, max, sum * - if granularity hit: Log, reset min/max */ bm_mycfg->tindex[id]->sum += tdiff; bm_mycfg->tindex[id]->last_sum += tdiff; bm_mycfg->tindex[id]->calls++; if (tdiff < bm_mycfg->tindex[id]->last_min) bm_mycfg->tindex[id]->last_min = tdiff; if (tdiff > bm_mycfg->tindex[id]->last_max) bm_mycfg->tindex[id]->last_max = tdiff; if (tdiff < bm_mycfg->tindex[id]->global_min) bm_mycfg->tindex[id]->global_min = tdiff; if (tdiff > bm_mycfg->tindex[id]->global_max) bm_mycfg->tindex[id]->global_max = tdiff; if ((bm_mycfg->tindex[id]->calls % bm_mycfg->granularity) == 0) { LM_GEN1(bm_mycfg->loglevel, "benchmark (timer %s [%d]): %llu [" " msgs/total/min/max/avg - LR:" " %i/%llu/%llu/%llu/%f | GB: %llu/%llu/%llu/%llu/%f]\n", bm_mycfg->tindex[id]->name, id, tdiff, bm_mycfg->granularity, bm_mycfg->tindex[id]->last_sum, bm_mycfg->tindex[id]->last_min, bm_mycfg->tindex[id]->last_max, ((double)bm_mycfg->tindex[id]->last_sum)/bm_mycfg->granularity, bm_mycfg->tindex[id]->calls, bm_mycfg->tindex[id]->sum, bm_mycfg->tindex[id]->global_min, bm_mycfg->tindex[id]->global_max, ((double)bm_mycfg->tindex[id]->sum)/bm_mycfg->tindex[id]->calls); bm_mycfg->tindex[id]->last_sum = 0; bm_mycfg->tindex[id]->last_max = 0; bm_mycfg->tindex[id]->last_min = 0xffffffff; } return 1; } int bm_log_timer(struct sip_msg* _msg, char* timer, char* mystr) { return _bm_log_timer((unsigned int)(unsigned long)timer); } int _bm_register_timer(char *tname, int mode, unsigned int *id) { benchmark_timer_t *bmt = 0; benchmark_timer_t **tidx = 0; if(tname==NULL || id==NULL || bm_mycfg==NULL || strlen(tname)==0 || strlen(tname)>BM_NAME_LEN-1) return -1; bmt = bm_mycfg->timers; while(bmt) { if(strcmp(bmt->name, tname)==0) { *id = bmt->id; return 0; } bmt = bmt->next; } if(mode==0) return -1; bmt = (benchmark_timer_t*)shm_malloc(sizeof(benchmark_timer_t)); if(bmt==0) { LM_ERR("no more shm\n"); return -1; } memset(bmt, 0, sizeof(benchmark_timer_t)); /* private memory, otherwise we have races */ bmt->start = (bm_timeval_t*)pkg_malloc(sizeof(bm_timeval_t)); if(bmt->start == NULL) { shm_free(bmt); LM_ERR("no more pkg\n"); return -1; } memset(bmt->start, 0, sizeof(bm_timeval_t)); strcpy(bmt->name, tname); if(bm_mycfg->timers==0) { bmt->id = 0; bm_mycfg->timers = bmt; } else { bmt->id = bm_mycfg->timers->id+1; bmt->next = bm_mycfg->timers; bm_mycfg->timers = bmt; } /* do the indexing */ if(bmt->id%10==0) { if(bm_mycfg->tindex!=NULL) tidx = bm_mycfg->tindex; bm_mycfg->tindex = (benchmark_timer_t**)shm_malloc((10+bmt->id)* sizeof(benchmark_timer_t*)); if(bm_mycfg->tindex==0) { LM_ERR("no more share memory\n"); if(tidx!=0) shm_free(tidx); return -1; } memset(bm_mycfg->tindex, 0, (10+bmt->id)*sizeof(benchmark_timer_t*)); if(tidx!=0) { memcpy(bm_mycfg->tindex, tidx, bmt->id*sizeof(benchmark_timer_t*)); shm_free(tidx); } } bm_mycfg->tindex[bmt->id] = bmt; bm_mycfg->nrtimers = bmt->id + 1; bm_reset_timer(bmt->id); *id = bmt->id; LM_DBG("timer [%s] added with index <%u>\n", bmt->name, bmt->id); return 0; } /*! \brief API Binding */ int load_bm( struct bm_binds *bmb) { if(bmb==NULL) return -1; bmb->bm_register = _bm_register_timer; bmb->bm_start = _bm_start_timer; bmb->bm_log = _bm_log_timer; return 1; } static inline char * pkg_strndup( char* _p, int _len) { char *s; s = (char*)pkg_malloc(_len+1); if (s==NULL) return NULL; memcpy(s,_p,_len); s[_len] = 0; return s; } /*! \name TimerMIfunctions MI functions */ /*@{ */ /*! \brief * Expects 1 node: 0 for disable, 1 for enable */ struct mi_root* mi_bm_enable_global(struct mi_root *cmd, void *param) { struct mi_node *node; char *p1, *e1; long int v1; node = cmd->node.kids; if ((node == NULL) || (node->next != NULL)) return init_mi_tree( 400, MI_MISSING_PARM_S, MI_MISSING_PARM_LEN); p1 = pkg_strndup(node->value.s, node->value.len); v1 = strtol(p1, &e1, 0); if ((*e1 != '\0') || (*p1 == '\0')) { pkg_free(p1); return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); } if ((v1 < -1) || (v1 > 1)) { pkg_free(p1); return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); } bm_mycfg->enable_global = v1; pkg_free(p1); return init_mi_tree( 200, MI_OK_S, MI_OK_LEN); } struct mi_root* mi_bm_enable_timer(struct mi_root *cmd, void *param) { struct mi_node *node; char *p1, *p2, *e2; long int v2; unsigned int id; node = cmd->node.kids; if ((node == NULL) || (node->next == NULL) || (node->next->next != NULL)) return init_mi_tree( 400, MI_MISSING_PARM_S, MI_MISSING_PARM_LEN); p1 = pkg_strndup(node->value.s, node->value.len); p2 = pkg_strndup(node->next->value.s, node->next->value.len); if(!p1 || !p2) goto error; if(_bm_register_timer(p1, 0, &id)!=0) { pkg_free(p1); pkg_free(p2); return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); } v2 = strtol(p2, &e2, 0); pkg_free(p1); if (*e2 != '\0' || *p2 == '\0') { pkg_free(p2); return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); } pkg_free(p2); if ((v2 < 0) || (v2 > 1)) return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); bm_mycfg->timers[id].enabled = v2; return init_mi_tree( 200, MI_OK_S, MI_OK_LEN); error: if(p1) pkg_free(p1); if(p2) pkg_free(p2); return init_mi_tree(500, MI_INTERNAL_ERR_S, MI_INTERNAL_ERR_LEN); } struct mi_root* mi_bm_granularity(struct mi_root *cmd, void *param) { struct mi_node *node; char *p1, *e1; long int v1; node = cmd->node.kids; if ((node == NULL) || (node->next != NULL)) return init_mi_tree( 400, MI_MISSING_PARM_S, MI_MISSING_PARM_LEN); p1 = pkg_strndup(node->value.s, node->value.len); v1 = strtol(p1, &e1, 0); if ((*e1 != '\0') || (*p1 == '\0')) { pkg_free(p1); return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); } pkg_free(p1); if (v1 < 1) return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); bm_mycfg->granularity = v1; return init_mi_tree( 200, MI_OK_S, MI_OK_LEN); } struct mi_root* mi_bm_loglevel(struct mi_root *cmd, void *param) { struct mi_node *node; char *p1, *e1; long int v1; node = cmd->node.kids; if ((node == NULL) || (node->next != NULL)) return init_mi_tree( 400, MI_MISSING_PARM_S, MI_MISSING_PARM_LEN); p1 = pkg_strndup(node->value.s, node->value.len); v1 = strtol(p1, &e1, 0); if ((*e1 != '\0') || (*p1 == '\0')) { pkg_free(p1); return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); } pkg_free(p1); if ((v1 < -3) || (v1 > 4)) /* Maximum log levels */ return init_mi_tree( 400, MI_BAD_PARM_S, MI_BAD_PARM_LEN); bm_mycfg->enable_global = v1; return init_mi_tree( 200, MI_OK_S, MI_OK_LEN); } /*@} */ /*! \brief PV get function for time diff */ static int bm_get_time_diff(struct sip_msg *msg, pv_param_t *param, pv_value_t *res) { if(msg==NULL) return -1; return pv_get_sintval(msg, param, res, _bm_last_time_diff); } static inline int fixup_bm_timer(void** param, int param_no) { unsigned int tid = 0; if (param_no == 1) { if((_bm_register_timer((char*)(*param), 1, &tid))!=0) { LM_ERR("cannot register timer [%s]\n", (char*)(*param)); return E_UNSPEC; } pkg_free(*param); *param = (void*)(unsigned long)tid; } return 0; } /* End of file */