[Asterisk-code-review] res odbc: Add basic query logging. (asterisk[master])
Friendly Automation
asteriskteam at digium.com
Mon Feb 11 08:35:04 CST 2019
Friendly Automation has submitted this change and it was merged. ( https://gerrit.asterisk.org/10967 )
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(-)
Approvals:
Kevin Harwell: Looks good to me, but someone else must approve
George Joseph: Looks good to me, approved
Friendly Automation: Approved for Submit
diff --git a/apps/app_voicemail.c b/apps/app_voicemail.c
index 3223af6..a5a3691 100644
--- a/apps/app_voicemail.c
+++ b/apps/app_voicemail.c
@@ -3855,7 +3855,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);
@@ -4378,7 +4378,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 feb62e9..eed809a 100644
--- a/cdr/cdr_adaptive_odbc.c
+++ b/cdr/cdr_adaptive_odbc.c
@@ -338,7 +338,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 54ca1b9..e7dd9c0 100644
--- a/cdr/cdr_odbc.c
+++ b/cdr/cdr_odbc.c
@@ -153,7 +153,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 04d3734..12f4a06 100644
--- a/cel/cel_odbc.c
+++ b/cel/cel_odbc.c
@@ -323,7 +323,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 9a124c1..126a339 100644
--- a/funcs/func_odbc.c
+++ b/funcs/func_odbc.c
@@ -462,7 +462,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 6eea305..62d8dc3 100644
--- a/res/res_config_odbc.c
+++ b/res/res_config_odbc.c
@@ -114,7 +114,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");
@@ -632,7 +632,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");
@@ -870,7 +870,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);
@@ -894,7 +894,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 a9fe7c7..da8700d 100644
--- a/res/res_odbc.c
+++ b/res/res_odbc.c
@@ -88,6 +88,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;
@@ -176,6 +188,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)
@@ -355,18 +368,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.
@@ -386,11 +433,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;
@@ -402,6 +497,10 @@
}
}
+ if (obj->parent->logging) {
+ ast_atomic_fetchadd_int(&obj->parent->queries_executed, +1);
+ }
+
return res;
}
@@ -469,7 +568,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 };
@@ -497,6 +596,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) ||
@@ -545,6 +646,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;
+ }
}
}
@@ -571,6 +679,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));
@@ -657,6 +767,16 @@
}
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 @@
*/
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/10967
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings
Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I173cf4928b10754478a6a8c27dfa96ede0f058a6
Gerrit-Change-Number: 10967
Gerrit-PatchSet: 1
Gerrit-Owner: Joshua C. Colp <jcolp at digium.com>
Gerrit-Reviewer: Friendly Automation (1000185)
Gerrit-Reviewer: George Joseph <gjoseph at digium.com>
Gerrit-Reviewer: Kevin Harwell <kharwell at digium.com>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20190211/2edf93f5/attachment-0001.html>
More information about the asterisk-code-review
mailing list