]> git.ipfire.org Git - thirdparty/asterisk.git/commitdiff
res_odbc: Add basic query logging.
authorJoshua Colp <jcolp@digium.com>
Wed, 6 Feb 2019 12:16:01 +0000 (12:16 +0000)
committerJoshua Colp <jcolp@digium.com>
Thu, 7 Feb 2019 14:11:13 +0000 (14:11 +0000)
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 a2f6c36b84c5923793a7da7988b88509ea419bce..6a29a20c81c1c83eb6e07fcfc2ee510dd11afa79 100644 (file)
@@ -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);
index 321a646314d40892e059e574f7214b86d58f107f..d810f9c3fd22e6ae3fba2c49e0475a3c09f819cf 100644 (file)
@@ -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);
index aed7499501275dae3bc289ce9cec83c2515a9910..455217afa9aef3b8cc622d3d9223b0514f42469d 100644 (file)
@@ -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);
index ec2feaba950792d3f6c52dc1e194971b78805cbf..f6b6321bad0356ae33433e7922f7b1b627e83a2e 100644 (file)
@@ -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);
index c69f55637555ccc428e49969ce355ed079e69acc..58671fc4af235b78a583aa2594f3d2e75bdd5826 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 70f02b8570bc0175ec2d06d1c2a655d422d6d0ff..fc5fe2bd0c6fd899eb02d19fb3f93661b872bed3 100644 (file)
@@ -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;
index 4286272fcce0e37a3be02db479fd164deed6c574..9a38915bc1b61d75f6e7362d85ed5dd8678e31f8 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;
 };
 
@@ -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
index 8e54b47882337bb9993ef0f69528520607fe3580..a9c349566d0e9429c3d1e4de53b343f64d0f9358 100644 (file)
@@ -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);
index cd588ee69afe7275b38c6396f37e0b2d6df68da3..5b79bd433f607fdd9626f6d44487581904a46c0c 100644 (file)
@@ -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);