diff --git a/apps/app_voicemail.c b/apps/app_voicemail.c
index a2f6c36b84c5923793a7da7988b88509ea419bce..6a29a20c81c1c83eb6e07fcfc2ee510dd11afa79 100644
--- a/apps/app_voicemail.c
+++ b/apps/app_voicemail.c
@@ -3838,7 +3838,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);
@@ -4361,7 +4361,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);
diff --git a/cdr/cdr_adaptive_odbc.c b/cdr/cdr_adaptive_odbc.c
index 321a646314d40892e059e574f7214b86d58f107f..d810f9c3fd22e6ae3fba2c49e0475a3c09f819cf 100644
--- a/cdr/cdr_adaptive_odbc.c
+++ b/cdr/cdr_adaptive_odbc.c
@@ -327,7 +327,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);
diff --git a/cdr/cdr_odbc.c b/cdr/cdr_odbc.c
index aed7499501275dae3bc289ce9cec83c2515a9910..455217afa9aef3b8cc622d3d9223b0514f42469d 100644
--- a/cdr/cdr_odbc.c
+++ b/cdr/cdr_odbc.c
@@ -155,7 +155,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);
diff --git a/cel/cel_odbc.c b/cel/cel_odbc.c
index ec2feaba950792d3f6c52dc1e194971b78805cbf..f6b6321bad0356ae33433e7922f7b1b627e83a2e 100644
--- a/cel/cel_odbc.c
+++ b/cel/cel_odbc.c
@@ -325,7 +325,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);
diff --git a/configs/samples/res_odbc.conf.sample b/configs/samples/res_odbc.conf.sample
index c69f55637555ccc428e49969ce355ed079e69acc..58671fc4af235b78a583aa2594f3d2e75bdd5826 100644
--- a/configs/samples/res_odbc.conf.sample
+++ b/configs/samples/res_odbc.conf.sample
@@ -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
diff --git a/funcs/func_odbc.c b/funcs/func_odbc.c
index 70f02b8570bc0175ec2d06d1c2a655d422d6d0ff..fc5fe2bd0c6fd899eb02d19fb3f93661b872bed3 100644
--- a/funcs/func_odbc.c
+++ b/funcs/func_odbc.c
@@ -464,7 +464,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;
diff --git a/include/asterisk/res_odbc.h b/include/asterisk/res_odbc.h
index 4286272fcce0e37a3be02db479fd164deed6c574..9a38915bc1b61d75f6e7362d85ed5dd8678e31f8 100644
--- a/include/asterisk/res_odbc.h
+++ b/include/asterisk/res_odbc.h
@@ -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
diff --git a/res/res_config_odbc.c b/res/res_config_odbc.c
index 8e54b47882337bb9993ef0f69528520607fe3580..a9c349566d0e9429c3d1e4de53b343f64d0f9358 100644
--- a/res/res_config_odbc.c
+++ b/res/res_config_odbc.c
@@ -116,7 +116,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");
@@ -634,7 +634,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");
@@ -872,7 +872,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);
@@ -896,7 +896,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);
diff --git a/res/res_odbc.c b/res/res_odbc.c
index cd588ee69afe7275b38c6396f37e0b2d6df68da3..5b79bd433f607fdd9626f6d44487581904a46c0c 100644
--- a/res/res_odbc.c
+++ b/res/res_odbc.c
@@ -91,6 +91,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;
@@ -188,6 +200,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)
@@ -367,18 +380,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.
@@ -398,11 +445,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;
@@ -414,6 +509,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;
}
@@ -481,7 +580,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 };
@@ -509,6 +608,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) ||
@@ -557,6 +658,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;
+ }
}
}
@@ -583,6 +691,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));
@@ -665,6 +775,16 @@ static char *handle_cli_odbc_show(struct ast_cli_entry *e, int cmd, struct ast_c
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 @@ 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);