[Asterisk-code-review] res odbc: Add basic query logging. (asterisk[13])
Joshua C. Colp
asteriskteam at digium.com
Thu Feb 7 08:22:44 CST 2019
Joshua C. Colp has uploaded this change for review. ( https://gerrit.asterisk.org/10965
Change subject: res_odbc: Add basic query logging.
......................................................................
res_odbc: Add basic query logging.
When Asterisk is connected and used with a database the response
time of the database can cause problems in Asterisk if it is long.
Normally the only way to see this problem would be to retrieve a
backtrace from Asterisk and examine where things are blocked, or
examine the database to see if there is any indication of a
problem.
This change adds some basic query logging to make it easier to
investigate such a problem. When logging is enabled res_odbc will
now keep track of the number of queries executed, as well as the
query that has taken the longest time to execute. There is also
an option which will cause a WARNING message to be output if a
query takes longer than a configurable amount of time to execute.
This makes it easier and clearer for users that their database may
be experiencing a problem that could impact Asterisk.
ASTERISK-28277
Change-Id: I173cf4928b10754478a6a8c27dfa96ede0f058a6
---
M apps/app_voicemail.c
M cdr/cdr_adaptive_odbc.c
M cdr/cdr_odbc.c
M cel/cel_odbc.c
M configs/samples/res_odbc.conf.sample
M funcs/func_odbc.c
M include/asterisk/res_odbc.h
M res/res_config_odbc.c
M res/res_odbc.c
9 files changed, 168 insertions(+), 11 deletions(-)
git pull ssh://gerrit.asterisk.org:29418/asterisk refs/changes/65/10965/1
diff --git a/apps/app_voicemail.c b/apps/app_voicemail.c
index a2f6c36..6a29a20 100644
--- a/apps/app_voicemail.c
+++ b/apps/app_voicemail.c
@@ -3838,7 +3838,7 @@
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);
@@ -4361,7 +4361,7 @@
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);
diff --git a/cdr/cdr_adaptive_odbc.c b/cdr/cdr_adaptive_odbc.c
index 321a646..d810f9c 100644
--- a/cdr/cdr_adaptive_odbc.c
+++ b/cdr/cdr_adaptive_odbc.c
@@ -327,7 +327,7 @@
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);
diff --git a/cdr/cdr_odbc.c b/cdr/cdr_odbc.c
index aed7499..455217a 100644
--- a/cdr/cdr_odbc.c
+++ b/cdr/cdr_odbc.c
@@ -155,7 +155,7 @@
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);
diff --git a/cel/cel_odbc.c b/cel/cel_odbc.c
index ec2feab..f6b6321 100644
--- a/cel/cel_odbc.c
+++ b/cel/cel_odbc.c
@@ -325,7 +325,7 @@
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);
diff --git a/configs/samples/res_odbc.conf.sample b/configs/samples/res_odbc.conf.sample
index c69f556..58671fc 100644
--- a/configs/samples/res_odbc.conf.sample
+++ b/configs/samples/res_odbc.conf.sample
@@ -65,6 +65,20 @@
; 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
diff --git a/funcs/func_odbc.c b/funcs/func_odbc.c
index 70f02b8..fc5fe2b 100644
--- a/funcs/func_odbc.c
+++ b/funcs/func_odbc.c
@@ -464,7 +464,7 @@
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;
diff --git a/include/asterisk/res_odbc.h b/include/asterisk/res_odbc.h
index 4286272..9a38915 100644
--- a/include/asterisk/res_odbc.h
+++ b/include/asterisk/res_odbc.h
@@ -51,6 +51,7 @@
char function[80];
int lineno;
#endif
+ char *sql_text; /*!< The SQL text currently executing */
AST_LIST_ENTRY(odbc_obj) list;
};
@@ -161,6 +162,22 @@
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
* \param tablename Tablename to describe
diff --git a/res/res_config_odbc.c b/res/res_config_odbc.c
index 8e54b47..a9c3495 100644
--- a/res/res_config_odbc.c
+++ b/res/res_config_odbc.c
@@ -116,7 +116,7 @@
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");
@@ -634,7 +634,7 @@
/* 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");
@@ -872,7 +872,7 @@
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);
@@ -896,7 +896,7 @@
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);
diff --git a/res/res_odbc.c b/res/res_odbc.c
index cd588ee..5b79bd4 100644
--- a/res/res_odbc.c
+++ b/res/res_odbc.c
@@ -91,6 +91,18 @@
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;
@@ -188,6 +200,7 @@
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)
@@ -367,18 +380,52 @@
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.
@@ -398,11 +445,59 @@
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;
@@ -414,6 +509,10 @@
}
}
+ if (obj->parent->logging) {
+ ast_atomic_fetchadd_int(&obj->parent->queries_executed, +1);
+ }
+
return res;
}
@@ -481,7 +580,7 @@
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 };
@@ -509,6 +608,8 @@
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) ||
@@ -557,6 +658,13 @@
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;
+ }
}
}
@@ -583,6 +691,8 @@
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));
@@ -665,6 +775,16 @@
ast_cli(a->fd, " Name: %s\n DSN: %s\n", class->name, class->dsn);
ast_cli(a->fd, " Last connection attempt: %s\n", timestr);
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);
@@ -713,6 +833,12 @@
*/
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);
--
To view, visit https://gerrit.asterisk.org/10965
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings
Gerrit-Project: asterisk
Gerrit-Branch: 13
Gerrit-MessageType: newchange
Gerrit-Change-Id: I173cf4928b10754478a6a8c27dfa96ede0f058a6
Gerrit-Change-Number: 10965
Gerrit-PatchSet: 1
Gerrit-Owner: Joshua C. Colp <jcolp at digium.com>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20190207/4db9e1e9/attachment-0001.html>
More information about the asterisk-code-review
mailing list