Skip to content

Commit

Permalink
MDEV-7648: Extra data in ANALYZE FORMAT=JSON $stmt
Browse files Browse the repository at this point in the history 
Show total execution time (r_total_time_ms) for various parts of the
query:
1. time spent in SELECTs
2. time spent reading rows from storage engines

#2 currently gets the data from P_S.
  • Loading branch information
@spetrunia
spetrunia committed Mar 7, 2015
1 parent 2288b84 commit 1626e0d
Show file tree
Hide file tree
Showing 12 changed files with 218 additions and 3 deletions.
2 changes: 2 additions & 0 deletions include/mysql/psi/mysql_table.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,7 @@
#define PSI_CALL_get_table_share PSI_TABLE_CALL(get_table_share)
#define PSI_CALL_release_table_share PSI_TABLE_CALL(release_table_share)
#define PSI_CALL_drop_table_share PSI_TABLE_CALL(drop_table_share)
#define PSI_CALL_get_table_current_stats PSI_TABLE_CALL(get_table_current_stats)
#else
#define PSI_CALL_unbind_table(A1) /* no-op */
#define PSI_CALL_rebind_table(A1,A2,A3) NULL
Expand All @@ -45,6 +46,7 @@
#define PSI_CALL_get_table_share(A1,A2) NULL
#define PSI_CALL_release_table_share(A1) /* no-op */
#define PSI_CALL_drop_table_share(A1,A2,A3,A4,A5) /* no-op */
#define PSI_CALL_get_table_current_stats(A1,A2,A3) /* no-op */
#endif

/**
Expand Down
12 changes: 12 additions & 0 deletions include/mysql/psi/psi.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1921,6 +1921,16 @@ typedef struct PSI_digest_locker* (*digest_add_token_v1_t)
typedef int (*set_thread_connect_attrs_v1_t)(const char *buffer, uint length,
const void *from_cs);

/**
Get current row read statistics for the specific instance of a table
@param table Instance of table we need statistics for
@param count OUT Number of operations
@param sum OUT Total duration of operations
*/
typedef void (*get_table_current_stats_v1_t)(PSI_table *table,
ulonglong *count,
ulonglong *sum);

/**
Performance Schema Interface, version 1.
@since PSI_VERSION_1
Expand Down Expand Up @@ -2122,6 +2132,8 @@ struct PSI_v1
digest_add_token_v1_t digest_add_token;
/** @sa set_thread_connect_attrs_v1_t. */
set_thread_connect_attrs_v1_t set_thread_connect_attrs;
/** @sa get_table_current_stats_v1 */
get_table_current_stats_v1_t get_table_current_stats;
};

/** @} (end of group Group_PSI_v1) */
Expand Down
4 changes: 4 additions & 0 deletions include/mysql/psi/psi_abi_v1.h.pp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -512,6 +512,9 @@
(struct PSI_digest_locker *locker, uint token, struct OPAQUE_LEX_YYSTYPE *yylval);
typedef int (*set_thread_connect_attrs_v1_t)(const char *buffer, uint length,
const void *from_cs);
typedef void (*get_table_current_stats_v1_t)(PSI_table *table,
ulonglong *count,
ulonglong *sum);
struct PSI_v1
{
register_mutex_v1_t register_mutex;
Expand Down Expand Up @@ -612,6 +615,7 @@
digest_start_v1_t digest_start;
digest_add_token_v1_t digest_add_token;
set_thread_connect_attrs_v1_t set_thread_connect_attrs;
get_table_current_stats_v1_t get_table_current_stats;
};
typedef struct PSI_v1 PSI;
typedef struct PSI_mutex_info_v1 PSI_mutex_info;
Expand Down
25 changes: 25 additions & 0 deletions mysql-test/r/analyze_format_json.result
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,12 +7,15 @@ EXPLAIN
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": "REPLACED",
"table": {
"table_name": "t0",
"access_type": "ALL",
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 30,
"attached_condition": "(t0.a < 3)"
Expand All @@ -32,12 +35,15 @@ EXPLAIN
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": "REPLACED",
"table": {
"table_name": "t0",
"access_type": "ALL",
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 0,
"attached_condition": "((t0.a > 9) and (t0.a is not null))"
Expand Down Expand Up @@ -69,12 +75,15 @@ EXPLAIN
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": "REPLACED",
"table": {
"table_name": "t0",
"access_type": "ALL",
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100,
"attached_condition": "(t0.a is not null)"
Expand All @@ -90,6 +99,7 @@ EXPLAIN
"r_loops": 10,
"rows": 1,
"r_rows": 1,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 40,
"attached_condition": "(t1.b < 4)"
Expand All @@ -107,12 +117,15 @@ EXPLAIN
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": "REPLACED",
"table": {
"table_name": "tbl1",
"access_type": "ALL",
"r_loops": 1,
"rows": 100,
"r_rows": 100,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 20,
"attached_condition": "(tbl1.b < 20)"
Expand All @@ -124,6 +137,7 @@ EXPLAIN
"r_loops": 1,
"rows": 100,
"r_rows": 100,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 60,
"attached_condition": "(tbl2.b < 60)"
Expand All @@ -140,12 +154,15 @@ EXPLAIN
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": "REPLACED",
"table": {
"table_name": "tbl1",
"access_type": "ALL",
"r_loops": 1,
"rows": 100,
"r_rows": 100,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 20,
"attached_condition": "(tbl1.b < 20)"
Expand All @@ -157,6 +174,7 @@ EXPLAIN
"r_loops": 1,
"rows": 100,
"r_rows": 100,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 60,
"attached_condition": "(tbl2.b < 60)"
Expand All @@ -182,12 +200,15 @@ EXPLAIN
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": "REPLACED",
"table": {
"table_name": "t1",
"access_type": "ALL",
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100,
"attached_condition": "(t1.a is not null)"
Expand All @@ -203,6 +224,7 @@ EXPLAIN
"r_loops": 10,
"rows": 2,
"r_rows": 0.2,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 100,
"using_index": true
Expand All @@ -226,12 +248,15 @@ EXPLAIN
{
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": "REPLACED",
"table": {
"table_name": "t1",
"access_type": "ALL",
"r_loops": 1,
"rows": 10,
"r_rows": 10,
"r_total_time_ms": "REPLACED",
"filtered": 100,
"r_filtered": 50,
"attached_condition": "(test.t1.a < 5)"
Expand Down
8 changes: 8 additions & 0 deletions mysql-test/t/analyze_format_json.test
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,28 +9,34 @@ create table t0 (a int);
INSERT INTO t0 VALUES (0),(1),(2),(3),(4),(5),(6),(7),(8),(9);

--echo # r_filtered=30%, because 3 rows match: 0,1,2
--replace_regex /"r_total_time_ms": [0-9]*[.]?[0-9]*/"r_total_time_ms": "REPLACED"/
analyze format=json select * from t0 where a<3;

create table t1 (a int, b int, c int, key(a));
insert into t1 select A.a*10 + B.a, A.a*10 + B.a, A.a*10 + B.a from t0 A, t0 B;

--replace_regex /"r_total_time_ms": [0-9]*[.]?[0-9]*/"r_total_time_ms": "REPLACED"/
analyze
select * from t0, t1 where t1.a=t0.a and t0.a > 9;
--replace_regex /"r_total_time_ms": [0-9]*[.]?[0-9]*/"r_total_time_ms": "REPLACED"/
analyze format=json
select * from t0, t1 where t1.a=t0.a and t0.a > 9;

analyze
select * from t0, t1 where t1.a=t0.a and t1.b<4;

--replace_regex /"r_total_time_ms": [0-9]*[.]?[0-9]*/"r_total_time_ms": "REPLACED"/
analyze format=json
select * from t0, t1 where t1.a=t0.a and t1.b<4;

analyze
select * from t1 tbl1, t1 tbl2 where tbl1.b<2 and tbl2.b>5;

--replace_regex /"r_total_time_ms": [0-9]*[.]?[0-9]*/"r_total_time_ms": "REPLACED"/
analyze format=json
select * from t1 tbl1, t1 tbl2 where tbl1.b<20 and tbl2.b<60;

--replace_regex /"r_total_time_ms": [0-9]*[.]?[0-9]*/"r_total_time_ms": "REPLACED"/
analyze format=json
select * from t1 tbl1, t1 tbl2 where tbl1.b<20 and tbl2.b<60 and tbl1.c > tbl2.c;

Expand All @@ -47,6 +53,7 @@ insert into t1 values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9);
create table t2 (a int, key(a));
insert into t2 values (0),(1);

--replace_regex /"r_total_time_ms": [0-9]*[.]?[0-9]*/"r_total_time_ms": "REPLACED"/
analyze format=json select * from t1 straight_join t2 force index(a) where t2.a=t1.a;

drop table t1,t2;
Expand All @@ -62,6 +69,7 @@ select database();
connect (con1,localhost,root,,*NO-ONE*);
connection con1;
select database();
--replace_regex /"r_total_time_ms": [0-9]*[.]?[0-9]*/"r_total_time_ms": "REPLACED"/
analyze format=json select * from test.t1 where t1.a<5;
disconnect con1;
connection default;
Expand Down
4 changes: 4 additions & 0 deletions sql/mysqld.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -314,6 +314,9 @@ arg_cmp_func Arg_comparator::comparator_matrix[6][2] =
{&Arg_comparator::compare_decimal, &Arg_comparator::compare_e_decimal},
{&Arg_comparator::compare_datetime, &Arg_comparator::compare_e_datetime}};

/* Timer info to be used by the SQL layer */
MY_TIMER_INFO sys_timer_info;

/* static variables */

#ifdef HAVE_PSI_INTERFACE
Expand Down Expand Up @@ -5458,6 +5461,7 @@ int mysqld_main(int argc, char **argv)
#ifdef WITH_PERFSCHEMA_STORAGE_ENGINE
pfs_param.m_pfs_instrument= const_cast<char*>("");
#endif /* WITH_PERFSCHEMA_STORAGE_ENGINE */
my_timer_init(&sys_timer_info);

int ho_error __attribute__((unused))= handle_early_options();

Expand Down
3 changes: 3 additions & 0 deletions sql/mysqld.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@
#include "sql_cmd.h"
#include <my_rnd.h>
#include "my_pthread.h"
#include "my_rdtsc.h"

class THD;
struct handlerton;
Expand Down Expand Up @@ -60,6 +61,8 @@ typedef Bitmap<((MAX_INDEXES+7)/8*8)> key_map; /* Used for finding keys */
#define OPT_SESSION SHOW_OPT_SESSION
#define OPT_GLOBAL SHOW_OPT_GLOBAL

extern MY_TIMER_INFO sys_timer_info;

/*
Values for --slave-parallel-mode
Must match order in slave_parallel_mode_typelib in sys_vars.cc.
Expand Down
47 changes: 46 additions & 1 deletion sql/sql_explain.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -732,7 +732,12 @@ void Explain_select::print_explain_json(Explain_query *query,
*/
writer->add_member("query_block").start_object();
writer->add_member("select_id").add_ll(select_id);


if (is_analyze && time_tracker.get_loops())
{
writer->add_member("r_loops").add_ll(time_tracker.get_loops());
writer->add_member("r_total_time_ms").add_double(time_tracker.get_time_ms());
}
if (exec_const_cond)
{
writer->add_member("const_condition");
Expand Down Expand Up @@ -1289,6 +1294,9 @@ void Explain_table_access::print_explain_json(Explain_query *query,
}
else
writer->add_null();

op_tracker.end_tracking();
op_tracker.print_json(writer);
}

/* `filtered` */
Expand Down Expand Up @@ -1971,3 +1979,40 @@ void create_explain_query_if_not_exists(LEX *lex, MEM_ROOT *mem_root)
create_explain_query(lex, mem_root);
}

//////////////////////////////////////////////////////////////////////////////
//
//////////////////////////////////////////////////////////////////////////////

void Table_op_tracker::start_tracking(TABLE *table)
{
//TODO: will this compile without P_S ?
start_count= end_count= 0;
if ((psi_table= table->file->m_psi))
{
PSI_CALL_get_table_current_stats(psi_table, &start_count, &start_sum);
}
}


void Table_op_tracker::end_tracking()
{
if (psi_table)
{
PSI_CALL_get_table_current_stats(psi_table, &end_count, &end_sum);
}
}

void Table_op_tracker::print_json(Json_writer *writer)
{
if (start_count != end_count)
{
/*
We have time in picoseconds, we want to print in milli-seconds
picosecond is sec* 10^ -12
millisecond is sec * 10^-3
*/
double ms= double(end_sum - start_sum) / 1e9;
writer->add_member("r_total_time_ms").add_double(ms);
}
}

Loading

0 comments on commit 1626e0d

Please sign in to comment.