sysmocom
/
asterisk
11
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Merge "res_odbc: Add basic query logging." into 16

This commit is contained in:
Joshua C. Colp 2019-02-11 08:39:31 -06:00 committed by Gerrit Code Review
parent 2cf3931379 44254d548b
commit 2070f62bb6
9 changed files with 168 additions and 11 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
apps/app_voicemail.c
View File

@ -3855,7 +3855,7 @@ static SQLHSTMT generic_prepare(struct odbc_obj *obj, void *data)
ast_log(AST_LOG_WARNING, "SQL Alloc Handle failed!\n");
return NULL;
}
res = SQLPrepare(stmt, (unsigned char *) gps->sql, SQL_NTS);
res = ast_odbc_prepare(obj, stmt, gps->sql);
if (!SQL_SUCCEEDED(res)) {
ast_log(AST_LOG_WARNING, "SQL Prepare failed![%s]\n", gps->sql);
SQLFreeHandle(SQL_HANDLE_STMT, stmt);
@ -4378,7 +4378,7 @@ static SQLHSTMT insert_data_cb(struct odbc_obj *obj, void *vdata)
if (!ast_strlen_zero(data->category)) {
SQLBindParameter(stmt, 13, SQL_PARAM_INPUT, SQL_C_CHAR, SQL_CHAR, strlen(data->category), 0, (void *) data->category, 0, NULL);
}
res = SQLExecDirect(stmt, (unsigned char *) data->sql, SQL_NTS);
res = ast_odbc_execute_sql(obj, stmt, data->sql);
if (!SQL_SUCCEEDED(res)) {
ast_log(AST_LOG_WARNING, "SQL Direct Execute failed!\n");
SQLFreeHandle(SQL_HANDLE_STMT, stmt);

2
cdr/cdr_adaptive_odbc.c
View File

@ -338,7 +338,7 @@ static SQLHSTMT generic_prepare(struct odbc_obj *obj, void *data)
return NULL;
}
res = SQLPrepare(stmt, (unsigned char *) data, SQL_NTS);
res = ast_odbc_prepare(obj, stmt, data);
if ((res != SQL_SUCCESS) && (res != SQL_SUCCESS_WITH_INFO)) {
ast_log(LOG_WARNING, "SQL Prepare failed![%s]\n", (char *) data);
SQLGetDiagField(SQL_HANDLE_STMT, stmt, 1, SQL_DIAG_NUMBER, &numfields, SQL_IS_INTEGER, &diagbytes);

2
cdr/cdr_odbc.c
View File

@ -153,7 +153,7 @@ static SQLHSTMT execute_cb(struct odbc_obj *obj, void *data)
SQLBindParameter(stmt, i + 2, SQL_PARAM_INPUT, SQL_C_SLONG, SQL_INTEGER, 0, 0, &cdr->sequence, 0, NULL);
}
ODBC_res = SQLExecDirect(stmt, (unsigned char *)sqlcmd, SQL_NTS);
ODBC_res = ast_odbc_execute_sql(obj, stmt, sqlcmd);
if ((ODBC_res != SQL_SUCCESS) && (ODBC_res != SQL_SUCCESS_WITH_INFO)) {
ast_log(LOG_WARNING, "cdr_odbc: Error in ExecDirect: %d, query is: %s\n", ODBC_res, sqlcmd);

2
cel/cel_odbc.c
View File

@ -323,7 +323,7 @@ static SQLHSTMT generic_prepare(struct odbc_obj *obj, void *data)
return NULL;
}
res = SQLPrepare(stmt, (unsigned char *)sql, SQL_NTS);
res = ast_odbc_prepare(obj, stmt, sql);
if ((res != SQL_SUCCESS) && (res != SQL_SUCCESS_WITH_INFO)) {
ast_log(LOG_WARNING, "SQL Prepare failed![%s]\n", sql);
SQLGetDiagField(SQL_HANDLE_STMT, stmt, 1, SQL_DIAG_NUMBER, &numfields, SQL_IS_INTEGER, &diagbytes);

14
configs/samples/res_odbc.conf.sample
View File

@ -65,6 +65,20 @@ pre-connect => yes
; information before we attempt another connection? This increases
; responsiveness, when a database resource is not working.
;negative_connection_cache => 300
;
; Enable query logging. This keeps track of the number of prepared queries
; and executed queries as well as the query that has taken the longest to
; execute. This can be useful for determining the latency with a database.
; The data can be viewed using the "odbc show" CLI command.
; Note that only successful queries are logged currently.
;logging => yes
;
; Slow query limit. If a query exceeds the given amount of time (in milliseconds)
; when executing then a WARNING message will be output to indicate that there
; may be a problem. Note that logging must be set to "yes" for this to occur. By
; default this is set to 5000 milliseconds (or 5 seconds). If you would like to
; disable the WARNING message it can be set to "0".
;slow_query_limit => 5000
[mysql2]
enabled => no

2
funcs/func_odbc.c
View File

@ -462,7 +462,7 @@ static SQLHSTMT execute(struct odbc_obj *obj, void *data, int silent)
return NULL;
}
res = SQLExecDirect(stmt, (unsigned char *)sql, SQL_NTS);
res = ast_odbc_execute_sql(obj, stmt, sql);
if ((res != SQL_SUCCESS) && (res != SQL_SUCCESS_WITH_INFO) && (res != SQL_NO_DATA)) {
if (res == SQL_ERROR && !silent) {
int i;

17
include/asterisk/res_odbc.h
View File

@ -51,6 +51,7 @@ struct odbc_obj {
char function[80];
int lineno;
#endif
char *sql_text; /*!< The SQL text currently executing */
AST_LIST_ENTRY(odbc_obj) list;
};
@ -160,6 +161,22 @@ SQLHSTMT ast_odbc_direct_execute(struct odbc_obj *obj, SQLHSTMT (*exec_cb)(struc
*/
SQLHSTMT ast_odbc_prepare_and_execute(struct odbc_obj *obj, SQLHSTMT (*prepare_cb)(struct odbc_obj *obj, void *data), void *data);
/*!
* \brief Prepares a SQL query on a statement.
* \param obj The ODBC object
* \param stmt The statement
* \parma sql The SQL query
* \note This should be used in place of SQLPrepare
*/
int ast_odbc_prepare(struct odbc_obj *obj, SQLHSTMT *stmt, const char *sql);
/*! \brief Execute a nonprepared SQL query.
* \param obj The ODBC object
* \param sql The SQL query
* \note This should be used in place of SQLExecDirect
*/
SQLRETURN ast_odbc_execute_sql(struct odbc_obj *obj, SQLHSTMT *stmt, const char *sql);
/*!
* \brief Find or create an entry describing the table specified.
* \param database Name of an ODBC class on which to query the table

8
res/res_config_odbc.c
View File

@ -114,7 +114,7 @@ static SQLHSTMT custom_prepare(struct odbc_obj *obj, void *data)
ast_debug(1, "Skip: %llu; SQL: %s\n", cps->skip, cps->sql);
res = SQLPrepare(stmt, (unsigned char *)cps->sql, SQL_NTS);
res = ast_odbc_prepare(obj, stmt, cps->sql);
if ((res != SQL_SUCCESS) && (res != SQL_SUCCESS_WITH_INFO)) {
if (res == SQL_ERROR) {
ast_odbc_print_errors(SQL_HANDLE_STMT, stmt, "SQL Prepare");
@ -632,7 +632,7 @@ static SQLHSTMT update2_prepare(struct odbc_obj *obj, void *data)
/* Done with the table metadata */
ast_odbc_release_table(tableptr);
res = SQLPrepare(stmt, (unsigned char *)ast_str_buffer(sql), SQL_NTS);
res = ast_odbc_prepare(obj, stmt, ast_str_buffer(sql));
if ((res != SQL_SUCCESS) && (res != SQL_SUCCESS_WITH_INFO)) {
if (res == SQL_ERROR) {
ast_odbc_print_errors(SQL_HANDLE_STMT, stmt, "SQL Prepare");
@ -870,7 +870,7 @@ static SQLHSTMT length_determination_odbc_prepare(struct odbc_obj *obj, void *da
return NULL;
}
res = SQLPrepare(sth, (unsigned char *)q->sql, SQL_NTS);
res = ast_odbc_prepare(obj, sth, q->sql);
if ((res != SQL_SUCCESS) && (res != SQL_SUCCESS_WITH_INFO)) {
ast_verb(4, "Error in PREPARE %d\n", res);
SQLFreeHandle(SQL_HANDLE_STMT, sth);
@ -894,7 +894,7 @@ static SQLHSTMT config_odbc_prepare(struct odbc_obj *obj, void *data)
return NULL;
}
res = SQLPrepare(sth, (unsigned char *)q->sql, SQL_NTS);
res = ast_odbc_prepare(obj, sth, q->sql);
if ((res != SQL_SUCCESS) && (res != SQL_SUCCESS_WITH_INFO)) {
ast_verb(4, "Error in PREPARE %d\n", res);
SQLFreeHandle(SQL_HANDLE_STMT, sth);

128
res/res_odbc.c
View File

@ -88,6 +88,18 @@ struct odbc_class
ast_cond_t cond;
/*! The total number of current connections */
size_t connection_cnt;
/*! Whether logging is enabled on this class or not */
unsigned int logging;
/*! The number of prepares executed on this class (total from all connections */
int prepares_executed;
/*! The number of queries executed on this class (total from all connections) */
int queries_executed;
/*! The longest execution time for a query executed on this class */
long longest_query_execution_time;
/*! The SQL query that took the longest to execute */
char *sql_text;
/*! Slow query limit (in milliseconds) */
unsigned int slowquerylimit;
};
static struct ao2_container *class_container;
@ -176,6 +188,7 @@ static void odbc_class_destructor(void *data)
SQLFreeHandle(SQL_HANDLE_ENV, class->env);
ast_mutex_destroy(&class->lock);
ast_cond_destroy(&class->cond);
ast_free(class->sql_text);
}
static void odbc_obj_destructor(void *data)
@ -355,18 +368,52 @@ int ast_odbc_clear_cache(const char *database, const char *tablename)
SQLHSTMT ast_odbc_direct_execute(struct odbc_obj *obj, SQLHSTMT (*exec_cb)(struct odbc_obj *obj, void *data), void *data)
{
struct timeval start;
SQLHSTMT stmt;
if (obj->parent->logging) {
start = ast_tvnow();
}
stmt = exec_cb(obj, data);
if (obj->parent->logging) {
long execution_time = ast_tvdiff_ms(ast_tvnow(), start);
if (obj->parent->slowquerylimit && execution_time > obj->parent->slowquerylimit) {
ast_log(LOG_WARNING, "SQL query '%s' took %ld milliseconds to execute on class '%s', this may indicate a database problem\n",
obj->sql_text, execution_time, obj->parent->name);
}
ast_mutex_lock(&obj->parent->lock);
if (execution_time > obj->parent->longest_query_execution_time || !obj->parent->sql_text) {
obj->parent->longest_query_execution_time = execution_time;
/* Due to the callback nature of the res_odbc API it's not possible to ensure that
* the SQL text is removed from the connection in all cases, so only if it becomes the
* new longest executing query do we steal the SQL text. In other cases what will happen
* is that the SQL text will be freed if the connection is released back to the class or
* if a new query is done on the connection.
*/
ast_free(obj->parent->sql_text);
obj->parent->sql_text = obj->sql_text;
obj->sql_text = NULL;
}
ast_mutex_unlock(&obj->parent->lock);
}
return stmt;
}
SQLHSTMT ast_odbc_prepare_and_execute(struct odbc_obj *obj, SQLHSTMT (*prepare_cb)(struct odbc_obj *obj, void *data), void *data)
{
struct timeval start;
int res = 0;
SQLHSTMT stmt;
if (obj->parent->logging) {
start = ast_tvnow();
}
/* This prepare callback may do more than just prepare -- it may also
* bind parameters, bind results, etc. The real key, here, is that
* when we disconnect, all handles become invalid for most databases.
@ -386,11 +433,59 @@ SQLHSTMT ast_odbc_prepare_and_execute(struct odbc_obj *obj, SQLHSTMT (*prepare_c
ast_log(LOG_WARNING, "SQL Execute error %d!\n", res);
SQLFreeHandle(SQL_HANDLE_STMT, stmt);
stmt = NULL;
} else if (obj->parent->logging) {
long execution_time = ast_tvdiff_ms(ast_tvnow(), start);
if (obj->parent->slowquerylimit && execution_time > obj->parent->slowquerylimit) {
ast_log(LOG_WARNING, "SQL query '%s' took %ld milliseconds to execute on class '%s', this may indicate a database problem\n",
obj->sql_text, execution_time, obj->parent->name);
}
ast_mutex_lock(&obj->parent->lock);
/* If this takes the record on longest query execution time, update the parent class
* with the information.
*/
if (execution_time > obj->parent->longest_query_execution_time || !obj->parent->sql_text) {
obj->parent->longest_query_execution_time = execution_time;
ast_free(obj->parent->sql_text);
obj->parent->sql_text = obj->sql_text;
obj->sql_text = NULL;
}
ast_mutex_unlock(&obj->parent->lock);
ast_atomic_fetchadd_int(&obj->parent->queries_executed, +1);
}
return stmt;
}
int ast_odbc_prepare(struct odbc_obj *obj, SQLHSTMT *stmt, const char *sql)
{
if (obj->parent->logging) {
/* It is possible for this connection to be reused without being
* released back to the class, so we free what may already exist
* and place the new SQL in.
*/
ast_free(obj->sql_text);
obj->sql_text = ast_strdup(sql);
ast_atomic_fetchadd_int(&obj->parent->prepares_executed, +1);
}
return SQLPrepare(stmt, (unsigned char *)sql, SQL_NTS);
}
SQLRETURN ast_odbc_execute_sql(struct odbc_obj *obj, SQLHSTMT *stmt, const char *sql)
{
if (obj->parent->logging) {
ast_free(obj->sql_text);
obj->sql_text = ast_strdup(sql);
ast_atomic_fetchadd_int(&obj->parent->queries_executed, +1);
}
return SQLExecDirect(stmt, (unsigned char *)sql, SQL_NTS);
}
int ast_odbc_smart_execute(struct odbc_obj *obj, SQLHSTMT stmt)
{
int res = 0;
@ -402,6 +497,10 @@ int ast_odbc_smart_execute(struct odbc_obj *obj, SQLHSTMT stmt)
}
}
if (obj->parent->logging) {
ast_atomic_fetchadd_int(&obj->parent->queries_executed, +1);
}
return res;
}
@ -469,7 +568,7 @@ static int load_odbc_config(void)
struct ast_variable *v;
char *cat;
const char *dsn, *username, *password, *sanitysql;
int enabled, bse, conntimeout, forcecommit, isolation, maxconnections;
int enabled, bse, conntimeout, forcecommit, isolation, maxconnections, logging, slowquerylimit;
struct timeval ncache = { 0, 0 };
int preconnect = 0, res = 0;
struct ast_flags config_flags = { 0 };
@ -497,6 +596,8 @@ static int load_odbc_config(void)
forcecommit = 0;
isolation = SQL_TXN_READ_COMMITTED;
maxconnections = 1;
logging = 0;
slowquerylimit = 5000;
for (v = ast_variable_browse(config, cat); v; v = v->next) {
if (!strcasecmp(v->name, "pooling") ||
!strncasecmp(v->name, "share", 5) ||
@ -545,6 +646,13 @@ static int load_odbc_config(void)
ast_log(LOG_WARNING, "max_connections must be a positive integer\n");
maxconnections = 1;
}
} else if (!strcasecmp(v->name, "logging")) {
logging = ast_true(v->value);
} else if (!strcasecmp(v->name, "slow_query_limit")) {
if (sscanf(v->value, "%30d", &slowquerylimit) != 1) {
ast_log(LOG_WARNING, "slow_query_limit must be a positive integer\n");
slowquerylimit = 5000;
}
}
}
@ -571,6 +679,8 @@ static int load_odbc_config(void)
new->conntimeout = conntimeout;
new->negative_connection_cache = ncache;
new->maxconnections = maxconnections;
new->logging = logging;
new->slowquerylimit = slowquerylimit;
if (cat)
ast_copy_string(new->name, cat, sizeof(new->name));
@ -657,6 +767,16 @@ static char *handle_cli_odbc_show(struct ast_cli_entry *e, int cmd, struct ast_c
}
ast_cli(a->fd, " Number of active connections: %zd (out of %d)\n", class->connection_cnt, class->maxconnections);
ast_cli(a->fd, " Logging: %s\n", class->logging ? "Enabled" : "Disabled");
if (class->logging) {
ast_cli(a->fd, " Number of prepares executed: %d\n", class->prepares_executed);
ast_cli(a->fd, " Number of queries executed: %d\n", class->queries_executed);
ast_mutex_lock(&class->lock);
if (class->sql_text) {
ast_cli(a->fd, " Longest running SQL query: %s (%ld milliseconds)\n", class->sql_text, class->longest_query_execution_time);
}
ast_mutex_unlock(&class->lock);
}
ast_cli(a->fd, "\n");
}
ao2_ref(class, -1);
@ -705,6 +825,12 @@ void ast_odbc_release_obj(struct odbc_obj *obj)
*/
obj->parent = NULL;
/* Free the SQL text so that the next user of this connection has
* a fresh start.
*/
ast_free(obj->sql_text);
obj->sql_text = NULL;
ast_mutex_lock(&class->lock);
AST_LIST_INSERT_HEAD(&class->connections, obj, list);
ast_cond_signal(&class->cond);