statements_summary query_sample_text shows prepared statement form

[wwar]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. What did you do?

I ran tpcc against master, and then observed the workload in information_schema.statements_summary.

2. What did you expect to see?

I was really hoping to see query_sample_text so that I could take the query and run it through explain. Instead it showed only the prepared statement form - which is non-explainable.

3. What did you see instead?

mysql> select * from statements_summary where stmt_type='select' order by sum_latency desc limit 2\G
*************************** 1. row ***************************
       SUMMARY_BEGIN_TIME: 2020-04-20 20:30:00
         SUMMARY_END_TIME: 2020-04-20 21:00:00
                STMT_TYPE: select
              SCHEMA_NAME: tpcc
                   DIGEST: 79cdf6c3eccead898330bda0b5630d505010bed8dac509c9d1a4e485e9e29b60
              DIGEST_TEXT: select c_discount , c_last , c_credit , w_tax from customer , warehouse where w_id = ? and c_w_id = w_id and c_d_id = ? and c_id = ?
              TABLE_NAMES: tpcc.customer,tpcc.warehouse
              INDEX_NAMES: NULL
              SAMPLE_USER: root
               EXEC_COUNT: 16146
               SUM_ERRORS: 0
             SUM_WARNINGS: 0
              SUM_LATENCY: 36927867322
              MAX_LATENCY: 104421632
              MIN_LATENCY: 471610
              AVG_LATENCY: 2287121
        AVG_PARSE_LATENCY: 9622
        MAX_PARSE_LATENCY: 4654548
      AVG_COMPILE_LATENCY: 318677
      MAX_COMPILE_LATENCY: 5278069
         SUM_COP_TASK_NUM: 0
     MAX_COP_PROCESS_TIME: 0
  MAX_COP_PROCESS_ADDRESS: NULL
        MAX_COP_WAIT_TIME: 0
     MAX_COP_WAIT_ADDRESS: NULL
         AVG_PROCESS_TIME: 0
         MAX_PROCESS_TIME: 0
            AVG_WAIT_TIME: 0
            MAX_WAIT_TIME: 0
         AVG_BACKOFF_TIME: 0
         MAX_BACKOFF_TIME: 0
           AVG_TOTAL_KEYS: 0
           MAX_TOTAL_KEYS: 0
       AVG_PROCESSED_KEYS: 0
       MAX_PROCESSED_KEYS: 0
        AVG_PREWRITE_TIME: 0
        MAX_PREWRITE_TIME: 0
          AVG_COMMIT_TIME: 0
          MAX_COMMIT_TIME: 0
   AVG_GET_COMMIT_TS_TIME: 0
   MAX_GET_COMMIT_TS_TIME: 0
  AVG_COMMIT_BACKOFF_TIME: 0
  MAX_COMMIT_BACKOFF_TIME: 0
    AVG_RESOLVE_LOCK_TIME: 0
    MAX_RESOLVE_LOCK_TIME: 0
AVG_LOCAL_LATCH_WAIT_TIME: 0
MAX_LOCAL_LATCH_WAIT_TIME: 0
           AVG_WRITE_KEYS: 0
           MAX_WRITE_KEYS: 0
           AVG_WRITE_SIZE: 0
           MAX_WRITE_SIZE: 0
     AVG_PREWRITE_REGIONS: 0
     MAX_PREWRITE_REGIONS: 0
            AVG_TXN_RETRY: 0
            MAX_TXN_RETRY: 0
        SUM_BACKOFF_TIMES: 0
            BACKOFF_TYPES: NULL
                  AVG_MEM: 53512
                  MAX_MEM: 53512
        AVG_AFFECTED_ROWS: 0
               FIRST_SEEN: 2020-04-20 20:49:34
                LAST_SEEN: 2020-04-20 20:51:25
        QUERY_SAMPLE_TEXT: SELECT c_discount, c_last, c_credit, w_tax FROM customer, warehouse WHERE w_id = ? AND c_w_id = w_id AND c_d_id = ? AND c_id = ?
         PREV_SAMPLE_TEXT: 
              PLAN_DIGEST: d40707dd740e8032fe6a362a242c86f5bb6409008ae3e968c45833be2f8e3065
                     PLAN: 	Projection_7    	root	0.9999999999999999	tpcc.customer.c_discount, tpcc.customer.c_last, tpcc.customer.c_credit, tpcc.warehouse.w_tax
	└─HashJoin_8    	root	0.9999999999999999	CARTESIAN inner join
	  ├─Point_Get_10	root	1                 	table:customer, index:PRIMARY(c_w_id, c_d_id, c_id)
	  └─Point_Get_11	root	1                 	table:warehouse, handle:10

See the ? for values under query_sample_text. In MySQL the query sample shows something that is directly explainable. The digest_text shows the prepared statement form.

4. What version of TiDB are you using? (tidb-server -V or run select tidb_version(); on TiDB)

mysql> select tidb_version()\G
*************************** 1. row ***************************
tidb_version(): Release Version: v4.0.0-beta.2-302-g8c455e86c
Git Commit Hash: 8c455e86c136ac020129998c94f890448367f62a
Git Branch: master
UTC Build Time: 2020-04-21 02:25:12
GoVersion: go1.13.8
Race Enabled: false
TiKV Min Version: v3.0.0-60965b006877ca7234adaced7890d7b029ed1306
Check Table Before Drop: false
1 row in set (0.00 sec)

[morgo]

I looked into how MySQL handles this, and was a little dissapointed to discover that it does not. See: https://bugs.mysql.com/bug.php?id=80173

Here is some sample code to reproduce. TiDB will return the statement sample text with a placeholder vs. MySQL that will not even return the statement.

#include <string.h>
#include <stdio.h>
#include <stdlib.h>

#include <mysql.h>


int main(int argc, char * argv[])
{
    char sqlStr[300];

    MYSQL *mysql = mysql_init(NULL);
    if (mysql == NULL) {
        fprintf(stderr, "ERROR:mysql_init() failed.\n");
        exit(1);
    }

    /*
    if (mysql_real_connect(mysql, "127.0.0.1", "root", "msandbox", "test", 8023, NULL, 0) == NULL) {
        fprintf(stderr, "ERROR:mysql_real_connect() failed.\n");
        exit(1);
    }
    */

    if (mysql_real_connect(mysql, "127.0.0.1", "root", "", "test", 4000, NULL, 0) == NULL) {
        fprintf(stderr, "ERROR:mysql_real_connect() failed.\n");
        exit(1);
    }

    if (mysql_query (mysql, "DROP TABLE IF EXISTS t1") != 0) {
        fprintf(stderr, "Could not DROP TABLE t1: %s\n", mysql_error(mysql));
        exit(1);
    }

    if (mysql_query (mysql, "CREATE TABLE t1 (pk INT NOT NULL auto_increment PRIMARY KEY, s varchar(200))") != 0) {
        fprintf(stderr, "Could not CREATE TABLE t1: %s\n", mysql_error(mysql));
        exit(1);
    }

    // Perform an insert using the prepared statement API

    MYSQL_STMT *statement = NULL;
    statement = mysql_stmt_init(mysql);
    if (statement == NULL) {
        fprintf(stderr, "ERROR:mysql_stmt_init() failed.\n");
        exit(1);
    }

    strcpy (sqlStr, "INSERT INTO t1 (s) ValUeS (?)");

    if (mysql_stmt_prepare(statement, sqlStr, strlen(sqlStr))) {
        fprintf(stderr, "ERROR:mysql_stmt_prepare() failed. Error:%s\nsql:%s\n", mysql_stmt_error(statement), sqlStr);
        exit(1);
    }

    MYSQL_BIND input_bind[1];
    memset(input_bind, 0, sizeof(input_bind));
    float v1 = 3.14;
    unsigned long v1_len = sizeof(v1);

    input_bind[0].buffer_type = MYSQL_TYPE_FLOAT;
    input_bind[0].buffer = &v1;
    input_bind[0].buffer_length = sizeof(v1);
    input_bind[0].length = &v1_len;

    if (mysql_stmt_bind_param(statement, input_bind)) {
        fprintf(stderr, "ERROR:mysql_stmt_bind_param failed\n");
        exit(1);
    }

    if (mysql_stmt_execute(statement)) {
        fprintf(stderr, "mysql_stmt_execute(), failed. Error:%s\n", mysql_stmt_error(statement));
        exit(1);
    }

    // Now check how many rows match in performance_schema
    // MySQL returns zero rows due to https://bugs.mysql.com/bug.php?id=80173
    // MySQL: SELECT query_sample_text, digest_text FROM performance_schema.events_statements_summary_by_digest WHERE query_sample_text like 'INSERT INTO t1%'\G 
    // TiDB: SELECT query_sample_text, digest_text FROM information_schema.statements_summary WHERE query_sample_text like 'INSERT INTO t1%'\G 

}

In TiDB:

mysql> SELECT query_sample_text, digest_text FROM information_schema.statements_summary WHERE query_sample_text like 'INSERT INTO t1%'\G 
*************************** 1. row ***************************
query_sample_text: INSERT INTO t1 (s) ValUeS (?)
      digest_text: insert into `t1` ( `s` ) values ( ? )
1 row in set (0.00 sec)

[morgo]

Summarizing this issue:

TiDB will record the statement, but only in prepared statement form versus MySQL which will not record the statement.

TiDB is not strictly compatible with MySQL's performance schema, so it is possible that this could be fixed to be the actual statement. But given the MySQL behavior, it is a lower priority issue.