Description:
Slow log usually contains information about statements which are executed more than
long_query_time seconds. But when some application uses a prepared statement,
in the slow-log we can see only:
# User@Host: root[root] @ localhost.localdomain [127.0.0.1]
# Query_time: 7 Lock_time: 0 Rows_sent: 1 Rows_examined: 0
# administrator command: Prepare Execute;
Which really doesn't give any useful information about the query. This can be a feature
request, but, I think, that this rather a bug, as it doesn't do what it should.
How to repeat:
For example, in my.cnf file I've put these lines:
[mysqld]
log_slow_queries=/home/gleb/mysqls/logs/mysql.log-slow.a
long_query_time=1
And wrote a simple program, the code was taken from example in the manual, I've only
added a benchmark(1000000,md5(".....")):
#include<stdio.h>
#include<mysql.h>
#define def_host_name "127.0.0.1"
#define def_user_name "root"
#define def_password ""
#define def_db_name "test"
#define STRING_SIZE 50
#define DROP_SAMPLE_TABLE "DROP TABLE IF EXISTS test_table"
#define CREATE_SAMPLE_TABLE "CREATE TABLE test_table(col1 INT,\
col2 VARCHAR(40),\
col3 SMALLINT,\
col4 TIMESTAMP)"
#define INSERT_SAMPLE "INSERT INTO test_table(col1,col2,col3) VALUES(?,?,?)"
#define SELECT_SAMPLE "SELECT benchmark(1000000,md5('employees')),?,?,?"
MYSQL *conn,*mysql;
MYSQL_STMT *stmt;
MYSQL_BIND bind[3];
my_ulonglong affected_rows;
int param_count;
short small_data;
int int_data;
char str_data[STRING_SIZE];
unsigned long str_length;
my_bool is_null;
main (int argc,char *argv[])
{
conn=mysql_init(NULL);
if(conn==NULL)
{fprintf(stderr,"mysql_init() errrror");
exit(1);}
if(mysql_real_connect(
conn,
def_host_name,
def_user_name,
def_password,
def_db_name,
3718,
NULL,
0)==NULL)
{
fprintf(stderr,"error mysql_connfect Error:%u (%s)\n",
mysql_errno
(conn),mysql_error(conn));
exit(1);
};
mysql=conn;
if (mysql_query(mysql, DROP_SAMPLE_TABLE))
{
fprintf(stderr, " DROP TABLE failed\n");
fprintf(stderr, " %s\n", mysql_error(mysql));
exit(0);
}
if (mysql_query(mysql, CREATE_SAMPLE_TABLE))
{
fprintf(stderr, " CREATE TABLE failed\n");
fprintf(stderr, " %s\n", mysql_error(mysql));
exit(0);
}
/* Prepare an INSERT query with 3 parameters */
/* (the TIMESTAMP column is not named; the server */
/* will set it to the current date and time) */
stmt = mysql_stmt_init(mysql);
if (!stmt)
{
fprintf(stderr, " mysql_stmt_init(), out of memory\n");
exit(0);
}
if (mysql_stmt_prepare(stmt, SELECT_SAMPLE, strlen(SELECT_SAMPLE)))
{
fprintf(stderr, " mysql_stmt_prepare(), SELECTfailed\n");
fprintf(stderr, " %s\n", mysql_stmt_error(stmt));
exit(0);
}
fprintf(stdout, " prepare, INSERT successful\n");
/* Get the parameter count from the statement */
param_count= mysql_stmt_param_count(stmt);
fprintf(stdout, " total parameters in INSERT: %d\n", param_count);
if (param_count != 3) /* validate parameter count */
{
fprintf(stderr, " invalid parameter count returned by MySQL\n");
exit(0);
}
/* Bind the data for all 3 parameters */
memset(bind, 0, sizeof(bind));
/* INTEGER PARAM */
/* This is a number type, so there is no need to specify buffer_length */
bind[0].buffer_type= MYSQL_TYPE_LONG;
bind[0].buffer= (char *)&int_data;
bind[0].is_null= 0;
bind[0].length= 0;
/* STRING PARAM */
bind[1].buffer_type= MYSQL_TYPE_STRING;
bind[1].buffer= (char *)str_data;
bind[1].buffer_length= STRING_SIZE;
bind[1].is_null= 0;
bind[1].length= &str_length;
/* SMALLINT PARAM */
bind[2].buffer_type= MYSQL_TYPE_SHORT;
bind[2].buffer= (char *)&small_data;
bind[2].is_null= &is_null;
bind[2].length= 0;
/* Bind the buffers */
if (mysql_stmt_bind_param(stmt, bind))
{
fprintf(stderr, " mysql_stmt_bind_param() failed\n");
fprintf(stderr, " %s\n", mysql_stmt_error(stmt));
exit(0);
}
/* Specify the data values for the first row */
int_data= 10; /* integer */
strncpy(str_data, "MySQL", STRING_SIZE); /* string */
str_length= strlen(str_data);
/* INSERT SMALLINT data as NULL */
is_null= 1;
/* Execute the INSERT statement - 1*/
if (mysql_stmt_execute(stmt))
{
fprintf(stderr, " mysql_stmt_execute(), 1 failed\n");
fprintf(stderr, " %s\n", mysql_stmt_error(stmt));
exit(0);
}
/* Get the total number of affected rows */
affected_rows= mysql_stmt_affected_rows(stmt);
fprintf(stdout, " total affected rows(insert 1): %lu\n",
(unsigned long) affected_rows);
if (affected_rows != 1) /* validate affected rows */
{
fprintf(stderr, " invalid affected rows by MySQL\n");
exit(0);
}
/* Specify data values for second row, then re-execute the statement */
int_data= 1000;
strncpy(str_data, "The most popular Open Source database", STRING_SIZE);
str_length= strlen(str_data);
small_data= 1000; /* smallint */
is_null= 0; /* reset */
/* Execute the INSERT statement - 2*/
if (mysql_stmt_execute(stmt))
{
fprintf(stderr, " mysql_stmt_execute, 2 failed\n");
fprintf(stderr, " %s\n", mysql_stmt_error(stmt));
exit(0);
}
/* Get the total rows affected */
affected_rows= mysql_stmt_affected_rows(stmt);
fprintf(stdout, " total affected rows(insert 2): %lu\n",
(unsigned long) affected_rows);
if (affected_rows != 1) /* validate affected rows */
{
fprintf(stderr, " invalid affected rows by MySQL\n");
exit(0);
}
/* Close the statement */
if (mysql_stmt_close(stmt))
{
fprintf(stderr, " failed while closing the statement\n");
fprintf(stderr, " %s\n", mysql_stmt_error(stmt));
exit(0);
}
}
Suggested fix:
Put in the slow-log not only information that the prepared statement was executed, but
also a statement and binded parameters, or just a view of SQL query related to this prepared
statement. Something like:
# administrator command: Prepare Execute, Statement("select ?,benchmark(10000,md5("sf"))"), @1="a";
or just
# administrator command: Prepare Execute, Statement("select a,benchmark(10000,md5("sf"))");
Description: Slow log usually contains information about statements which are executed more than long_query_time seconds. But when some application uses a prepared statement, in the slow-log we can see only: # User@Host: root[root] @ localhost.localdomain [127.0.0.1] # Query_time: 7 Lock_time: 0 Rows_sent: 1 Rows_examined: 0 # administrator command: Prepare Execute; Which really doesn't give any useful information about the query. This can be a feature request, but, I think, that this rather a bug, as it doesn't do what it should. How to repeat: For example, in my.cnf file I've put these lines: [mysqld] log_slow_queries=/home/gleb/mysqls/logs/mysql.log-slow.a long_query_time=1 And wrote a simple program, the code was taken from example in the manual, I've only added a benchmark(1000000,md5(".....")): #include<stdio.h> #include<mysql.h> #define def_host_name "127.0.0.1" #define def_user_name "root" #define def_password "" #define def_db_name "test" #define STRING_SIZE 50 #define DROP_SAMPLE_TABLE "DROP TABLE IF EXISTS test_table" #define CREATE_SAMPLE_TABLE "CREATE TABLE test_table(col1 INT,\ col2 VARCHAR(40),\ col3 SMALLINT,\ col4 TIMESTAMP)" #define INSERT_SAMPLE "INSERT INTO test_table(col1,col2,col3) VALUES(?,?,?)" #define SELECT_SAMPLE "SELECT benchmark(1000000,md5('employees')),?,?,?" MYSQL *conn,*mysql; MYSQL_STMT *stmt; MYSQL_BIND bind[3]; my_ulonglong affected_rows; int param_count; short small_data; int int_data; char str_data[STRING_SIZE]; unsigned long str_length; my_bool is_null; main (int argc,char *argv[]) { conn=mysql_init(NULL); if(conn==NULL) {fprintf(stderr,"mysql_init() errrror"); exit(1);} if(mysql_real_connect( conn, def_host_name, def_user_name, def_password, def_db_name, 3718, NULL, 0)==NULL) { fprintf(stderr,"error mysql_connfect Error:%u (%s)\n", mysql_errno (conn),mysql_error(conn)); exit(1); }; mysql=conn; if (mysql_query(mysql, DROP_SAMPLE_TABLE)) { fprintf(stderr, " DROP TABLE failed\n"); fprintf(stderr, " %s\n", mysql_error(mysql)); exit(0); } if (mysql_query(mysql, CREATE_SAMPLE_TABLE)) { fprintf(stderr, " CREATE TABLE failed\n"); fprintf(stderr, " %s\n", mysql_error(mysql)); exit(0); } /* Prepare an INSERT query with 3 parameters */ /* (the TIMESTAMP column is not named; the server */ /* will set it to the current date and time) */ stmt = mysql_stmt_init(mysql); if (!stmt) { fprintf(stderr, " mysql_stmt_init(), out of memory\n"); exit(0); } if (mysql_stmt_prepare(stmt, SELECT_SAMPLE, strlen(SELECT_SAMPLE))) { fprintf(stderr, " mysql_stmt_prepare(), SELECTfailed\n"); fprintf(stderr, " %s\n", mysql_stmt_error(stmt)); exit(0); } fprintf(stdout, " prepare, INSERT successful\n"); /* Get the parameter count from the statement */ param_count= mysql_stmt_param_count(stmt); fprintf(stdout, " total parameters in INSERT: %d\n", param_count); if (param_count != 3) /* validate parameter count */ { fprintf(stderr, " invalid parameter count returned by MySQL\n"); exit(0); } /* Bind the data for all 3 parameters */ memset(bind, 0, sizeof(bind)); /* INTEGER PARAM */ /* This is a number type, so there is no need to specify buffer_length */ bind[0].buffer_type= MYSQL_TYPE_LONG; bind[0].buffer= (char *)&int_data; bind[0].is_null= 0; bind[0].length= 0; /* STRING PARAM */ bind[1].buffer_type= MYSQL_TYPE_STRING; bind[1].buffer= (char *)str_data; bind[1].buffer_length= STRING_SIZE; bind[1].is_null= 0; bind[1].length= &str_length; /* SMALLINT PARAM */ bind[2].buffer_type= MYSQL_TYPE_SHORT; bind[2].buffer= (char *)&small_data; bind[2].is_null= &is_null; bind[2].length= 0; /* Bind the buffers */ if (mysql_stmt_bind_param(stmt, bind)) { fprintf(stderr, " mysql_stmt_bind_param() failed\n"); fprintf(stderr, " %s\n", mysql_stmt_error(stmt)); exit(0); } /* Specify the data values for the first row */ int_data= 10; /* integer */ strncpy(str_data, "MySQL", STRING_SIZE); /* string */ str_length= strlen(str_data); /* INSERT SMALLINT data as NULL */ is_null= 1; /* Execute the INSERT statement - 1*/ if (mysql_stmt_execute(stmt)) { fprintf(stderr, " mysql_stmt_execute(), 1 failed\n"); fprintf(stderr, " %s\n", mysql_stmt_error(stmt)); exit(0); } /* Get the total number of affected rows */ affected_rows= mysql_stmt_affected_rows(stmt); fprintf(stdout, " total affected rows(insert 1): %lu\n", (unsigned long) affected_rows); if (affected_rows != 1) /* validate affected rows */ { fprintf(stderr, " invalid affected rows by MySQL\n"); exit(0); } /* Specify data values for second row, then re-execute the statement */ int_data= 1000; strncpy(str_data, "The most popular Open Source database", STRING_SIZE); str_length= strlen(str_data); small_data= 1000; /* smallint */ is_null= 0; /* reset */ /* Execute the INSERT statement - 2*/ if (mysql_stmt_execute(stmt)) { fprintf(stderr, " mysql_stmt_execute, 2 failed\n"); fprintf(stderr, " %s\n", mysql_stmt_error(stmt)); exit(0); } /* Get the total rows affected */ affected_rows= mysql_stmt_affected_rows(stmt); fprintf(stdout, " total affected rows(insert 2): %lu\n", (unsigned long) affected_rows); if (affected_rows != 1) /* validate affected rows */ { fprintf(stderr, " invalid affected rows by MySQL\n"); exit(0); } /* Close the statement */ if (mysql_stmt_close(stmt)) { fprintf(stderr, " failed while closing the statement\n"); fprintf(stderr, " %s\n", mysql_stmt_error(stmt)); exit(0); } } Suggested fix: Put in the slow-log not only information that the prepared statement was executed, but also a statement and binded parameters, or just a view of SQL query related to this prepared statement. Something like: # administrator command: Prepare Execute, Statement("select ?,benchmark(10000,md5("sf"))"), @1="a"; or just # administrator command: Prepare Execute, Statement("select a,benchmark(10000,md5("sf"))");