res_odbc: Add basic query logging.
authorJoshua Colp <jcolp@digium.com>
Wed, 6 Feb 2019 12:16:01 +0000 (12:16 +0000)
committerJoshua C. Colp <jcolp@digium.com>
Thu, 7 Feb 2019 14:23:14 +0000 (08:23 -0600)
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

apps/app_voicemail.c
cdr/cdr_adaptive_odbc.c
cdr/cdr_odbc.c
cel/cel_odbc.c
configs/samples/res_odbc.conf.sample
funcs/func_odbc.c
include/asterisk/res_odbc.h
res/res_config_odbc.c
res/res_odbc.c

index 3223af6..a5a3691 100644 (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);
index feb62e9..eed809a 100644 (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);
index 54ca1b9..e7dd9c0 100644 (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);
index 04d3734..12f4a06 100644 (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);
index c69f556..58671fc 100644 (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
index 9a124c1..126a339 100644 (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;
index 4286272..9a38915 100644 (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;
 };
 
@@ -161,6 +162,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
  * \param tablename Tablename to describe
index 6eea305..62d8dc3 100644 (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);
index a9fe7c7..da8700d 100644 (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);