mirror/mariadb
1
0
Fork 0
mirror of https://github.com/MariaDB/server.git synced 2025-01-16 12:02:42 +01:00
Code Issues Projects Releases Packages Wiki Activity Actions

MDEV-7648: Extra data in ANALYZE FORMAT=JSON $stmt

Browse source 
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.
This commit is contained in:
Sergei Petrunia 2015-03-07 22:47:28 +03:00
parent 2288b84df4
commit 1626e0d3d4
12 changed files with 218 additions and 3 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
include/mysql/psi/mysql_table.h
View file

@ -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
@ -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
/**

12
include/mysql/psi/psi.h
View file

@ -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
@ -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) */

4
include/mysql/psi/psi_abi_v1.h.pp
View file

@ -512,6 +512,9 @@ typedef struct PSI_digest_locker* (*digest_add_token_v1_t)
(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;
@ -612,6 +615,7 @@ struct PSI_v1
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;

25
mysql-test/r/analyze_format_json.result
View file

@ -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)"
@ -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))"
@ -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)"
@ -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)"
@ -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)"
@ -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)"
@ -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)"
@ -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)"
@ -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)"
@ -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
@ -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)"

8
mysql-test/t/analyze_format_json.test
View file

@ -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;
@ -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;
@ -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;

4
sql/mysqld.cc
View file

@ -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
@ -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();

3
sql/mysqld.h
View file

@ -26,6 +26,7 @@
#include "sql_cmd.h"
#include <my_rnd.h>
#include "my_pthread.h"
#include "my_rdtsc.h"
class THD;
struct handlerton;
@ -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.

47
sql/sql_explain.cc
View file

@ -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");
@ -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` */
@ -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);
}
}

77
sql/sql_explain.h
View file

@ -21,12 +21,16 @@ public:
bool append_str(MEM_ROOT *mem_root, const char *str);
};
class Json_writer;
/*
A class for collecting read statistics.
The idea is that we run several scans. Each scans gets rows, and then filters
some of them out. We count scans, rows, and rows left after filtering.
(note: at the moment, the class is not actually tied to a physical table.
It can be used to track reading from files, buffers, etc).
*/
class Table_access_tracker
@ -66,6 +70,72 @@ public:
};
/*
A class to track operations (currently, row reads) on a PSI_table.
*/
class Table_op_tracker
{
PSI_table *psi_table;
/* Table counter values at start. Sum is in picoseconds */
ulonglong start_sum;
ulonglong start_count;
/* Table counter values at end */
ulonglong end_sum;
ulonglong end_count;
public:
void start_tracking(TABLE *table);
// At the moment, print_json will call end_tracking.
void end_tracking();
// this may print nothing if the table was not tracked.
void print_json(Json_writer *writer);
};
#define ANALYZE_START_TRACKING(tracker) \
if (tracker) \
{ tracker->start_tracking(); }
#define ANALYZE_STOP_TRACKING(tracker) \
if (tracker) \
{ tracker->stop_tracking(); }
/*
A class for tracking execution time
*/
class Exec_time_tracker
{
ulonglong count;
ulonglong cycles;
ulonglong last_start;
public:
Exec_time_tracker() : count(0), cycles(0) {}
// interface for collecting time
void start_tracking()
{
last_start= my_timer_cycles();
}
void stop_tracking()
{
ulonglong last_end= my_timer_cycles();
count++;
cycles += last_end - last_start;
}
// interface for getting the time
//loops, starts, stops
ulonglong get_loops() { return count; }
double get_time_ms()
{
// convert 'cycles' to milliseconds.
return 1000 * ((double)cycles) / sys_timer_info.cycles.frequency;
}
};
/**************************************************************************************
Data structures for producing EXPLAIN outputs.
@ -82,8 +152,6 @@ const int FAKE_SELECT_LEX_ID= (int)UINT_MAX;
class Explain_query;
class Json_writer;
/*
A node can be either a SELECT, or a UNION.
*/
@ -231,6 +299,9 @@ public:
/* Global join attributes. In tabular form, they are printed on the first row */
bool using_temporary;
bool using_filesort;
/* ANALYZE members */
Exec_time_tracker time_tracker;
int print_explain(Explain_query *query, select_result_sink *output,
uint8 explain_flags, bool is_analyze);
@ -666,6 +737,7 @@ public:
/* Tracker for reading the table */
Table_access_tracker tracker;
Table_op_tracker op_tracker;
Table_access_tracker jbuf_tracker;
int print_explain(select_result_sink *output, uint8 explain_flags,
@ -735,6 +807,7 @@ public:
/* ANALYZE members and methods */
Table_access_tracker tracker;
//psergey-todo: io-tracker here.
virtual int print_explain(Explain_query *query, select_result_sink *output,
uint8 explain_flags, bool is_analyze);

4
sql/sql_select.cc
View file

@ -2390,7 +2390,9 @@ void JOIN::exec()
select_lex->select_number))
dbug_serve_apcs(thd, 1);
);
ANALYZE_START_TRACKING(tracker);
exec_inner();
ANALYZE_STOP_TRACKING(tracker);
DBUG_EXECUTE_IF("show_explain_probe_join_exec_end",
if (dbug_user_var_equals_int(thd,
@ -23417,6 +23419,7 @@ void JOIN_TAB::save_explain_data(Explain_table_access *eta, table_map prefix_tab
tab->tracker= &eta->tracker;
tab->jbuf_tracker= &eta->jbuf_tracker;
eta->op_tracker.start_tracking(table);
/* id and select_type are kept in Explain_select */
/* table */
@ -23855,6 +23858,7 @@ int JOIN::save_explain_data_intern(Explain_query *output, bool need_tmp_table,
Explain_select *xpl_sel;
explain_node= xpl_sel= new (output->mem_root) Explain_select(output->mem_root);
table_map used_tables=0;
tracker= &xpl_sel->time_tracker;
join->select_lex->set_explain_type(true);
xpl_sel->select_id= join->select_lex->select_number;

5
sql/sql_select.h
View file

@ -252,6 +252,7 @@ typedef struct st_join_table {
enum explain_extra_tag info;
Table_access_tracker *tracker;
Table_access_tracker *jbuf_tracker;
/*
Bitmap of TAB_INFO_* bits that encodes special line for EXPLAIN 'Extra'
@ -1260,6 +1261,8 @@ public:
OPTIMIZATION_DONE=2};
bool optimized; ///< flag to avoid double optimization in EXPLAIN
bool initialized; ///< flag to avoid double init_execution calls
Exec_time_tracker *tracker;
enum { QEP_NOT_PRESENT_YET, QEP_AVAILABLE, QEP_DELETED} have_query_plan;
@ -1354,6 +1357,8 @@ public:
no_rows_in_result_called= 0;
positions= best_positions= 0;
tracker= NULL;
all_fields= fields_arg;
if (&fields_list != &fields_arg) /* Avoid valgrind-warning */
fields_list= fields_arg;

30
storage/perfschema/pfs.cc
View file

@ -1728,6 +1728,34 @@ static void close_table_v1(PSI_table *table)
destroy_table(pfs);
}
/**
Used in ANALYZE-stmt: get current table statistics.
*/
static void get_table_current_stats_v1(PSI_table *table, ulonglong *count, ulonglong *sum)
{
PFS_table *pfs= reinterpret_cast<PFS_table*> (table);
if (unlikely(pfs == NULL))
{
*count= 0;
*sum= 0;
return;
}
longlong cur_count= 0;
longlong cur_sum= 0;
time_normalizer *normalizer= time_normalizer::get(wait_timer);
for (int i=0; i <= MAX_INDEXES; i++)
{
ulonglong wait= pfs->m_table_stat.m_index_stat[i].m_fetch.m_sum;
cur_sum += normalizer->wait_to_pico(wait);
cur_count += pfs->m_table_stat.m_index_stat[i].m_fetch.m_count;
}
*count= cur_count;
*sum= cur_sum;
}
static PSI_socket*
init_socket_v1(PSI_socket_key key, const my_socket *fd,
const struct sockaddr *addr, socklen_t addr_len)
@ -5245,6 +5273,8 @@ PSI_v1 PFS_v1=
pfs_digest_start_v1,
pfs_digest_add_token_v1,
set_thread_connect_attrs_v1,
/* MariaDB's extension: */
get_table_current_stats_v1
};
static void* get_interface(int version)