From 1626e0d3d48f56bd91239c4fcbc24595ee3a34e3 Mon Sep 17 00:00:00 2001 From: Sergei Petrunia Date: Sat, 7 Mar 2015 22:47:28 +0300 Subject: [PATCH 1/3] MDEV-7648: Extra data in ANALYZE FORMAT=JSON $stmt 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. --- include/mysql/psi/mysql_table.h | 2 + include/mysql/psi/psi.h | 12 ++++ include/mysql/psi/psi_abi_v1.h.pp | 4 ++ mysql-test/r/analyze_format_json.result | 25 ++++++++ mysql-test/t/analyze_format_json.test | 8 +++ sql/mysqld.cc | 4 ++ sql/mysqld.h | 3 + sql/sql_explain.cc | 47 ++++++++++++++- sql/sql_explain.h | 77 ++++++++++++++++++++++++- sql/sql_select.cc | 4 ++ sql/sql_select.h | 5 ++ storage/perfschema/pfs.cc | 30 ++++++++++ 12 files changed, 218 insertions(+), 3 deletions(-) diff --git a/include/mysql/psi/mysql_table.h b/include/mysql/psi/mysql_table.h index bd703d75e1f..a74fbef186f 100644 --- a/include/mysql/psi/mysql_table.h +++ b/include/mysql/psi/mysql_table.h @@ -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 /** diff --git a/include/mysql/psi/psi.h b/include/mysql/psi/psi.h index 30f2709be0f..51be70dde24 100644 --- a/include/mysql/psi/psi.h +++ b/include/mysql/psi/psi.h @@ -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) */ diff --git a/include/mysql/psi/psi_abi_v1.h.pp b/include/mysql/psi/psi_abi_v1.h.pp index fa2bf724b5e..bdae597733a 100644 --- a/include/mysql/psi/psi_abi_v1.h.pp +++ b/include/mysql/psi/psi_abi_v1.h.pp @@ -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; diff --git a/mysql-test/r/analyze_format_json.result b/mysql-test/r/analyze_format_json.result index 26625cbb75e..f3694b4278a 100644 --- a/mysql-test/r/analyze_format_json.result +++ b/mysql-test/r/analyze_format_json.result @@ -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)" diff --git a/mysql-test/t/analyze_format_json.test b/mysql-test/t/analyze_format_json.test index f57db1d76af..64bafd7ee32 100644 --- a/mysql-test/t/analyze_format_json.test +++ b/mysql-test/t/analyze_format_json.test @@ -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; diff --git a/sql/mysqld.cc b/sql/mysqld.cc index 2e6d88ef0a4..cde920a3678 100644 --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -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(""); #endif /* WITH_PERFSCHEMA_STORAGE_ENGINE */ + my_timer_init(&sys_timer_info); int ho_error __attribute__((unused))= handle_early_options(); diff --git a/sql/mysqld.h b/sql/mysqld.h index bfce719a280..b414e5168b2 100644 --- a/sql/mysqld.h +++ b/sql/mysqld.h @@ -26,6 +26,7 @@ #include "sql_cmd.h" #include #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. diff --git a/sql/sql_explain.cc b/sql/sql_explain.cc index aa16a744e83..873ed74a1a2 100644 --- a/sql/sql_explain.cc +++ b/sql/sql_explain.cc @@ -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); + } +} + diff --git a/sql/sql_explain.h b/sql/sql_explain.h index 970edf7800d..98b56ed88c0 100644 --- a/sql/sql_explain.h +++ b/sql/sql_explain.h @@ -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); diff --git a/sql/sql_select.cc b/sql/sql_select.cc index de713d6aca0..6c7e762b088 100644 --- a/sql/sql_select.cc +++ b/sql/sql_select.cc @@ -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; diff --git a/sql/sql_select.h b/sql/sql_select.h index a50ed130df8..7cff7912a0b 100644 --- a/sql/sql_select.h +++ b/sql/sql_select.h @@ -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; diff --git a/storage/perfschema/pfs.cc b/storage/perfschema/pfs.cc index fa87269a054..54a47d2333d 100644 --- a/storage/perfschema/pfs.cc +++ b/storage/perfschema/pfs.cc @@ -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 (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) From b273e4a5c0e2342cf407d451466df164adfb36c6 Mon Sep 17 00:00:00 2001 From: Sergei Petrunia Date: Tue, 24 Mar 2015 13:22:03 +0300 Subject: [PATCH 2/3] Better comments --- sql/sql_explain.h | 43 +++++++++++++++++++++++++++++++++++++++---- 1 file changed, 39 insertions(+), 4 deletions(-) diff --git a/sql/sql_explain.h b/sql/sql_explain.h index 98b56ed88c0..95114b197b1 100644 --- a/sql/sql_explain.h +++ b/sql/sql_explain.h @@ -15,6 +15,43 @@ Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA */ +/* + +== EXPLAIN/ANALYZE architecture == + +=== [SHOW] EXPLAIN data === +Query optimization produces two data structures: +1. execution data structures themselves (eg. JOINs, JOIN_TAB, etc, etc) +2. Explain data structures. + +#2 are self contained set of data structures that has sufficient info to +produce output of SHOW EXPLAIN, EXPLAIN [FORMAT=JSON], or +ANALYZE [FORMAT=JSON], without accessing the execution data structures. + +(the only exception is that Explain data structures keep Item* pointers, +and we require that one might call item->print(QT_EXPLAIN) when printing +FORMAT=JSON output) + +=== ANALYZE data === +EXPLAIN data structures have embedded ANALYZE data structures. These are +objects that are used to track how the parts of query plan were executed: +how many times each part of query plan was invoked, how many rows were +read/returned, etc. + +Each execution data structure keeps a direct pointer to its ANALYZE data +structure. It is needed so that execution code can quickly increment the +counters. + +(note that this increases the set of data that is frequently accessed +during the execution. What is the impact of this?) + +Since ANALYZE/EXPLAIN data structures are separated from execution data +structures, it is easy to have them survive until the end of the query, +where we can return ANALYZE [FORMAT=JSON] output to the user, or print +it into the slow query log. + +*/ + class String_list: public List { public: @@ -43,7 +80,6 @@ public: ha_rows r_scans; /* How many scans were ran on this join_tab */ ha_rows r_rows; /* How many rows we've got after that */ -// ha_rows r_rows_after_table_cond; /* Rows after applying the table condition */ ha_rows r_rows_after_where; /* Rows after applying attached part of WHERE */ bool has_scans() { return (r_scans != 0); } @@ -103,7 +139,7 @@ public: { tracker->stop_tracking(); } /* - A class for tracking execution time + A class for tracking time it takes to do a certain action */ class Exec_time_tracker { @@ -127,7 +163,6 @@ public: } // interface for getting the time - //loops, starts, stops ulonglong get_loops() { return count; } double get_time_ms() { @@ -710,7 +745,7 @@ public: // Valid if ET_USING tag is present Explain_quick_select *quick_info; - /* Non-NULL values means this tab uses "range checked for each record" */ + /* Non-NULL value means this tab uses "range checked for each record" */ Explain_range_checked_fer *range_checked_fer; bool full_scan_on_null_key; From 77e16ce7d65793451c640014b342d23a28fc1060 Mon Sep 17 00:00:00 2001 From: Sergei Petrunia Date: Tue, 24 Mar 2015 16:17:41 +0300 Subject: [PATCH 3/3] MDEV-7648: Extra data in ANALYZE FORMAT=JSON $stmt Switch from relying on PERFORMANCE_SCHEMA to using our own hooks for counting the time spent reading rows from tables. --- include/mysql/psi/mysql_table.h | 2 - include/mysql/psi/psi.h | 12 ------ include/mysql/psi/psi_abi_v1.h.pp | 4 -- sql/CMakeLists.txt | 1 + sql/handler.cc | 63 +++++++++++++++++++++++++------ sql/handler.h | 5 +++ sql/sql_analyze_stmt.h | 50 ++++++++++++++++++++++++ sql/sql_class.h | 22 ----------- sql/sql_explain.cc | 44 +++------------------ sql/sql_explain.h | 39 ++----------------- sql/sql_select.cc | 2 +- storage/perfschema/pfs.cc | 30 --------------- 12 files changed, 117 insertions(+), 157 deletions(-) create mode 100644 sql/sql_analyze_stmt.h diff --git a/include/mysql/psi/mysql_table.h b/include/mysql/psi/mysql_table.h index a74fbef186f..bd703d75e1f 100644 --- a/include/mysql/psi/mysql_table.h +++ b/include/mysql/psi/mysql_table.h @@ -37,7 +37,6 @@ #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 @@ -46,7 +45,6 @@ #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 /** diff --git a/include/mysql/psi/psi.h b/include/mysql/psi/psi.h index 51be70dde24..30f2709be0f 100644 --- a/include/mysql/psi/psi.h +++ b/include/mysql/psi/psi.h @@ -1921,16 +1921,6 @@ 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 @@ -2132,8 +2122,6 @@ 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) */ diff --git a/include/mysql/psi/psi_abi_v1.h.pp b/include/mysql/psi/psi_abi_v1.h.pp index bdae597733a..fa2bf724b5e 100644 --- a/include/mysql/psi/psi_abi_v1.h.pp +++ b/include/mysql/psi/psi_abi_v1.h.pp @@ -512,9 +512,6 @@ 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; @@ -615,7 +612,6 @@ 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; diff --git a/sql/CMakeLists.txt b/sql/CMakeLists.txt index c78fa73bb51..6dbad5c4af1 100644 --- a/sql/CMakeLists.txt +++ b/sql/CMakeLists.txt @@ -104,6 +104,7 @@ SET (SQL_SOURCE # added in MariaDB: sql_explain.h sql_explain.cc + sql_analyze_stmt.h sql_lifo_buffer.h sql_join_cache.h sql_join_cache.cc create_options.cc multi_range_read.cc opt_index_cond_pushdown.cc opt_subselect.cc diff --git a/sql/handler.cc b/sql/handler.cc index 7c70babfea8..4cd8d8e9aa1 100644 --- a/sql/handler.cc +++ b/sql/handler.cc @@ -43,6 +43,8 @@ #include "debug_sync.h" // DEBUG_SYNC #include "sql_audit.h" +#include "sql_analyze_stmt.h" // tracker in TABLE_IO_WAIT + #ifdef WITH_PARTITION_STORAGE_ENGINE #include "ha_partition.h" #endif @@ -54,6 +56,17 @@ #include "wsrep_mysqld.h" #include "wsrep.h" +#define TABLE_IO_WAIT(TRACKER, PSI, OP, INDEX, FLAGS, PAYLOAD) \ + { \ + if (unlikely(tracker)) \ + tracker->start_tracking(); \ + \ + MYSQL_TABLE_IO_WAIT(PSI, OP, INDEX, FLAGS, PAYLOAD); \ + \ + if (unlikely(tracker)) \ + tracker->stop_tracking(); \ + } + /* While we have legacy_db_type, we have this array to check for dups and to find handlerton from legacy_db_type. @@ -2560,12 +2573,38 @@ int handler::ha_close(void) status_var_add(table->in_use->status_var.rows_tmp_read, rows_tmp_read); PSI_CALL_close_table(m_psi); m_psi= NULL; /* instrumentation handle, invalid after close_table() */ + + /* Detach from ANALYZE tracker */ + tracker= NULL; DBUG_ASSERT(m_lock_type == F_UNLCK); DBUG_ASSERT(inited == NONE); DBUG_RETURN(close()); } +inline int handler::ha_write_tmp_row(uchar *buf) +{ + int error; + MYSQL_INSERT_ROW_START(table_share->db.str, table_share->table_name.str); + increment_statistics(&SSV::ha_tmp_write_count); + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_WRITE_ROW, MAX_KEY, 0, + { error= write_row(buf); }) + MYSQL_INSERT_ROW_DONE(error); + return error; +} + +inline int handler::ha_update_tmp_row(const uchar *old_data, uchar *new_data) +{ + int error; + MYSQL_UPDATE_ROW_START(table_share->db.str, table_share->table_name.str); + increment_statistics(&SSV::ha_tmp_update_count); + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_UPDATE_ROW, active_index, 0, + { error= update_row(old_data, new_data);}) + MYSQL_UPDATE_ROW_DONE(error); + return error; +} + + int handler::ha_rnd_next(uchar *buf) { int result; @@ -2574,7 +2613,7 @@ int handler::ha_rnd_next(uchar *buf) m_lock_type != F_UNLCK); DBUG_ASSERT(inited == RND); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, MAX_KEY, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, MAX_KEY, 0, { result= rnd_next(buf); }) if (!result) { @@ -2599,7 +2638,7 @@ int handler::ha_rnd_pos(uchar *buf, uchar *pos) /* TODO: Find out how to solve ha_rnd_pos when finding duplicate update. */ /* DBUG_ASSERT(inited == RND); */ - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, MAX_KEY, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, MAX_KEY, 0, { result= rnd_pos(buf, pos); }) increment_statistics(&SSV::ha_read_rnd_count); if (!result) @@ -2618,7 +2657,7 @@ int handler::ha_index_read_map(uchar *buf, const uchar *key, m_lock_type != F_UNLCK); DBUG_ASSERT(inited==INDEX); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, { result= index_read_map(buf, key, keypart_map, find_flag); }) increment_statistics(&SSV::ha_read_key_count); if (!result) @@ -2642,7 +2681,7 @@ int handler::ha_index_read_idx_map(uchar *buf, uint index, const uchar *key, DBUG_ASSERT(table_share->tmp_table != NO_TMP_TABLE || m_lock_type != F_UNLCK); DBUG_ASSERT(end_range == NULL); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, index, 0, { result= index_read_idx_map(buf, index, key, keypart_map, find_flag); }) increment_statistics(&SSV::ha_read_key_count); if (!result) @@ -2662,7 +2701,7 @@ int handler::ha_index_next(uchar * buf) m_lock_type != F_UNLCK); DBUG_ASSERT(inited==INDEX); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, { result= index_next(buf); }) increment_statistics(&SSV::ha_read_next_count); if (!result) @@ -2679,7 +2718,7 @@ int handler::ha_index_prev(uchar * buf) m_lock_type != F_UNLCK); DBUG_ASSERT(inited==INDEX); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, { result= index_prev(buf); }) increment_statistics(&SSV::ha_read_prev_count); if (!result) @@ -2695,7 +2734,7 @@ int handler::ha_index_first(uchar * buf) m_lock_type != F_UNLCK); DBUG_ASSERT(inited==INDEX); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, { result= index_first(buf); }) increment_statistics(&SSV::ha_read_first_count); if (!result) @@ -2711,7 +2750,7 @@ int handler::ha_index_last(uchar * buf) m_lock_type != F_UNLCK); DBUG_ASSERT(inited==INDEX); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, { result= index_last(buf); }) increment_statistics(&SSV::ha_read_last_count); if (!result) @@ -2727,7 +2766,7 @@ int handler::ha_index_next_same(uchar *buf, const uchar *key, uint keylen) m_lock_type != F_UNLCK); DBUG_ASSERT(inited==INDEX); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_FETCH_ROW, active_index, 0, { result= index_next_same(buf, key, keylen); }) increment_statistics(&SSV::ha_read_next_count); if (!result) @@ -5852,7 +5891,7 @@ int handler::ha_write_row(uchar *buf) mark_trx_read_write(); increment_statistics(&SSV::ha_write_count); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_WRITE_ROW, MAX_KEY, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_WRITE_ROW, MAX_KEY, 0, { error= write_row(buf); }) MYSQL_INSERT_ROW_DONE(error); @@ -5885,7 +5924,7 @@ int handler::ha_update_row(const uchar *old_data, uchar *new_data) mark_trx_read_write(); increment_statistics(&SSV::ha_update_count); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_UPDATE_ROW, active_index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_UPDATE_ROW, active_index, 0, { error= update_row(old_data, new_data);}) MYSQL_UPDATE_ROW_DONE(error); @@ -5913,7 +5952,7 @@ int handler::ha_delete_row(const uchar *buf) mark_trx_read_write(); increment_statistics(&SSV::ha_delete_count); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_DELETE_ROW, active_index, 0, + TABLE_IO_WAIT(tracker, m_psi, PSI_TABLE_DELETE_ROW, active_index, 0, { error= delete_row(buf);}) MYSQL_DELETE_ROW_DONE(error); if (unlikely(error)) diff --git a/sql/handler.h b/sql/handler.h index 5ef92088df5..b7b35bc2b06 100644 --- a/sql/handler.h +++ b/sql/handler.h @@ -1571,6 +1571,7 @@ typedef struct { #define UNDEF_NODEGROUP 65535 class Item; +class Exec_time_tracker; struct st_table_log_memory_entry; class partition_info; @@ -2594,6 +2595,9 @@ public: ulonglong rows_changed; /* One bigger than needed to avoid to test if key == MAX_KEY */ ulonglong index_rows_read[MAX_KEY+1]; + + /* ANALYZE time tracker, if present */ + Exec_time_tracker *tracker; Item *pushed_idx_cond; uint pushed_idx_cond_keyno; /* The index which the above condition is for */ @@ -2648,6 +2652,7 @@ public: ft_handler(0), inited(NONE), implicit_emptied(0), pushed_cond(0), next_insert_id(0), insert_id_for_cur_row(0), + tracker(NULL), pushed_idx_cond(NULL), pushed_idx_cond_keyno(MAX_KEY), auto_inc_intervals_count(0), diff --git a/sql/sql_analyze_stmt.h b/sql/sql_analyze_stmt.h new file mode 100644 index 00000000000..f83ae1a57a6 --- /dev/null +++ b/sql/sql_analyze_stmt.h @@ -0,0 +1,50 @@ +/* + Copyright (c) 2015 MariaDB Corporation Ab + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; version 2 of the License. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program; if not, write to the Free Software + Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA */ + + +/* + A class for tracking time it takes to do a certain action +*/ +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 + ulonglong get_loops() { return count; } + double get_time_ms() + { + // convert 'cycles' to milliseconds. + return 1000 * ((double)cycles) / sys_timer_info.cycles.frequency; + } +}; + diff --git a/sql/sql_class.h b/sql/sql_class.h index bd145bd4d28..75eb31755fa 100644 --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -5201,28 +5201,6 @@ inline int handler::ha_read_first_row(uchar *buf, uint primary_key) return error; } -inline int handler::ha_write_tmp_row(uchar *buf) -{ - int error; - MYSQL_INSERT_ROW_START(table_share->db.str, table_share->table_name.str); - increment_statistics(&SSV::ha_tmp_write_count); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_WRITE_ROW, MAX_KEY, 0, - { error= write_row(buf); }) - MYSQL_INSERT_ROW_DONE(error); - return error; -} - -inline int handler::ha_update_tmp_row(const uchar *old_data, uchar *new_data) -{ - int error; - MYSQL_UPDATE_ROW_START(table_share->db.str, table_share->table_name.str); - increment_statistics(&SSV::ha_tmp_update_count); - MYSQL_TABLE_IO_WAIT(m_psi, PSI_TABLE_UPDATE_ROW, active_index, 0, - { error= update_row(old_data, new_data);}) - MYSQL_UPDATE_ROW_DONE(error); - return error; -} - extern pthread_attr_t *get_connection_attrib(void); /** diff --git a/sql/sql_explain.cc b/sql/sql_explain.cc index 873ed74a1a2..9d82f4fe19f 100644 --- a/sql/sql_explain.cc +++ b/sql/sql_explain.cc @@ -1295,8 +1295,11 @@ void Explain_table_access::print_explain_json(Explain_query *query, else writer->add_null(); - op_tracker.end_tracking(); - op_tracker.print_json(writer); + if (op_tracker.get_loops()) + { + writer->add_member("r_total_time_ms"). + add_double(op_tracker.get_time_ms()); + } } /* `filtered` */ @@ -1979,40 +1982,3 @@ 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); - } -} - diff --git a/sql/sql_explain.h b/sql/sql_explain.h index 95114b197b1..50b351cf619 100644 --- a/sql/sql_explain.h +++ b/sql/sql_explain.h @@ -14,6 +14,7 @@ along with this program; if not, write to the Free Software Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA */ +#include "sql_analyze_stmt.h" /* @@ -105,7 +106,7 @@ public: inline void on_record_after_where() { r_rows_after_where++; } }; - +#if 0 /* A class to track operations (currently, row reads) on a PSI_table. */ @@ -128,7 +129,7 @@ public: // this may print nothing if the table was not tracked. void print_json(Json_writer *writer); }; - +#endif #define ANALYZE_START_TRACKING(tracker) \ if (tracker) \ @@ -138,38 +139,6 @@ public: if (tracker) \ { tracker->stop_tracking(); } -/* - A class for tracking time it takes to do a certain action -*/ -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 - ulonglong get_loops() { return count; } - double get_time_ms() - { - // convert 'cycles' to milliseconds. - return 1000 * ((double)cycles) / sys_timer_info.cycles.frequency; - } -}; /************************************************************************************** @@ -772,7 +741,7 @@ public: /* Tracker for reading the table */ Table_access_tracker tracker; - Table_op_tracker op_tracker; + Exec_time_tracker op_tracker; Table_access_tracker jbuf_tracker; int print_explain(select_result_sink *output, uint8 explain_flags, diff --git a/sql/sql_select.cc b/sql/sql_select.cc index 6c7e762b088..485efcc1128 100644 --- a/sql/sql_select.cc +++ b/sql/sql_select.cc @@ -23419,7 +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); + tab->table->file->tracker= &eta->op_tracker; /* id and select_type are kept in Explain_select */ /* table */ diff --git a/storage/perfschema/pfs.cc b/storage/perfschema/pfs.cc index 54a47d2333d..fa87269a054 100644 --- a/storage/perfschema/pfs.cc +++ b/storage/perfschema/pfs.cc @@ -1728,34 +1728,6 @@ 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 (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) @@ -5273,8 +5245,6 @@ 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)