Percona Server moved to https://jira.percona.com/projects/PS

Merge lp:~vlad-lesin/percona-server/5.6-query_response_time-rw-commands into lp:percona-server/5.6

  1. 5.6-query_response_time-rw-commands
  2. Merge into 5.6
Proposed by Vlad Lesin
Status: Merged
Approved by: Laurynas Biveinis
Approved revision: no longer in the source branch.
Merged at revision: 735
Proposed branch: lp:~vlad-lesin/percona-server/5.6-query_response_time-rw-commands
Merge into: lp:percona-server/5.6
Diff against target: 1349 lines (+1130/-30)
10 files modified
mysql-test/include/plugin.defs (+1/-1)
plugin/query_response_time/plugin.cc (+60/-2)
plugin/query_response_time/query_response_time.cc (+45/-24)
plugin/query_response_time/query_response_time.h (+8/-1)
plugin/query_response_time/tests/mtr/basic.result (+12/-0)
plugin/query_response_time/tests/mtr/query_response_time-rw-begin.inc (+16/-0)
plugin/query_response_time/tests/mtr/query_response_time-rw-end.inc (+10/-0)
plugin/query_response_time/tests/mtr/query_response_time-rw.result (+765/-0)
plugin/query_response_time/tests/mtr/query_response_time-rw.test (+201/-0)
sql/sp_instr.cc (+12/-2)
To merge this branch: bzr merge lp:~vlad-lesin/percona-server/5.6-query_response_time-rw-commands
Reviewer Review Type Date Requested Status
Laurynas Biveinis (community) Approve
Review via email: mp+243247@code.launchpad.net

Description of the change

This is one more implementation of https://blueprints.launchpad.net/percona-server/+spec/query-response-time-rw blueprint.

The previous implementation was based on MDL(https://code.launchpad.net/~vlad-lesin/percona-server/5.6-query_response_time-rw-MDL), i.e. if restrictive enough MDL is required then the query is treated as 'write'. But this implementation has a number of disadvantages:

- LOCK TABLES t1 WRITE would be blocked by an active FTWRL and thus, would be considered a "write"

- moreover, an INSERT/DELETE/UPDATE with an active LOCK TABLES ... WRITE would _not_ take any MDL locks (that would be handled by LOCK TABLES, which would either block or be blocked by FTWRL), so they would _not_ be considered "write" queries

- EXPLAIN INSERT/UPDATE/DELETE would be a considered a "write" query, though it is obviously not.

- updates to temporary tables will not be considered writes.

The current implementation is based on checking sql command flags. The downside is that queries which are supposed to change data but does not change it are treated as 'write'(for example 'UPDATE ... WHERE condition' when condition is false).

http://jenkins.percona.com/job/percona-server-5.6-param/762/

To post a comment you must log in.
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

    - Please revert rev 689 (its fix is already in the trunk), unlink
      its associated bug, and flatten 690/691 together. While at that,
      a rebase on the current trunk wouldn't hurt neither
    - Please update the blueprint for the read/write difference
      criteria, and what does the command flag criteria mean for the
      end user (including the "downside" from the MP description)
    - IMHO the testcase needs not bother with MyISAM testing, even
      more so as the current implementation is above the SE
      level. That would shorten .result three times
    - Please see the diff comments

review: Needs Fixing
Revision history for this message
Vlad Lesin (vlad-lesin) wrote :

> - IMHO the testcase needs not bother with MyISAM testing, even
> more so as the current implementation is above the SE
> level. That would shorten .result three times
I do not think so because this is regression test and it can be that test results depend on db engine for some implementations, if we change this implementation I want be sure we don't break the functionality for both MyISAM and InnoDB.

http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/801/

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

As discussed yesterday on IRC:

- THD::update_server_status uses utime_after_query too
do you know whether updating the field might cause the change of behavior somewhere else?
-
64 - query_response_time_collect(thd->utime_after_query - thd->utime_after_lock);
65 + query_response_time_collect(query_type, thd->utime_after_query - thd->start_utime);
before: utime after lock
after: start utime
why?

review: Needs Information
Revision history for this message
Vlad Lesin (vlad-lesin) wrote :

> As discussed yesterday on IRC:
>
> - THD::update_server_status uses utime_after_query too
> do you know whether updating the field might cause the change of behavior
> somewhere else?
I have checked the code and did not find side effects now. Moreover I ran tests and everything seems ok: http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/804/ .

> -
> 64 - query_response_time_collect(thd->utime_after_query -
> thd->utime_after_lock);
> 65 + query_response_time_collect(query_type, thd->utime_after_query -
> thd->start_utime);
> before: utime after lock
> after: start utime
> why?

I have changed it for some reason, but unfortunately I don't remember the reason. I tested "utime_after_lock" variant both with regression test and manually with different test cases and it works well so I decided to revert this line.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) :
review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'mysql-test/include/plugin.defs'
2--- mysql-test/include/plugin.defs 2014-12-01 15:25:32 +0000
3+++ mysql-test/include/plugin.defs 2015-02-04 16:22:40 +0000
4@@ -49,5 +49,5 @@
5 scalability_metrics plugin/scalability_metrics SCALABILITY_METRICS
6 adt_null plugin/audit_null AUDIT_NULL
7 audit_log plugin/audit_log AUDIT_LOG audit_log
8-query_response_time plugin/query_response_time PLUGIN_QUERY_RESPONSE_TIME QUERY_RESPONSE_TIME_AUDIT,QUERY_RESPONSE_TIME
9+query_response_time plugin/query_response_time PLUGIN_QUERY_RESPONSE_TIME QUERY_RESPONSE_TIME_AUDIT,QUERY_RESPONSE_TIME,QUERY_RESPONSE_TIME_READ,QUERY_RESPONSE_TIME_WRITE
10 handlersocket plugin/HandlerSocket-Plugin-for-MySQL HANDLER_SOCKET
11
12=== modified file 'plugin/query_response_time/plugin.cc'
13--- plugin/query_response_time/plugin.cc 2014-09-25 06:33:00 +0000
14+++ plugin/query_response_time/plugin.cc 2015-02-04 16:22:40 +0000
15@@ -19,6 +19,7 @@
16 #include <sql_show.h>
17 #include <mysql/plugin_audit.h>
18 #include <sp_instr.h>
19+#include <sql_parse.h>
20 #include "query_response_time.h"
21
22
23@@ -130,6 +131,31 @@
24 if (event_general->event_subclass == MYSQL_AUDIT_GENERAL_STATUS &&
25 opt_query_response_time_stats)
26 {
27+ /*
28+ Get sql command id of currently executed statement
29+ inside of stored function or procedure. If the command is "PREPARE"
30+ don't get the statement inside of "PREPARE". If the statement
31+ is not inside of stored function or procedure get sql command id
32+ of the statement itself.
33+ */
34+ enum_sql_command sql_command=
35+ (
36+ thd->lex->sql_command != SQLCOM_PREPARE &&
37+ thd->sp_runtime_ctx &&
38+ thd->stmt_arena &&
39+ ((sp_lex_instr *)thd->stmt_arena)->get_command() >= 0
40+ ) ?
41+ (enum_sql_command)((sp_lex_instr *)thd->stmt_arena)->get_command() :
42+ thd->lex->sql_command;
43+ if (sql_command == SQLCOM_EXECUTE)
44+ {
45+ LEX_STRING *name= &thd->lex->prepared_stmt_name;
46+ Statement *stmt=
47+ (Statement *)thd->stmt_map.find_by_name(name);
48+ sql_command= stmt->lex->sql_command;
49+ }
50+ QUERY_TYPE query_type=
51+ (sql_command_flags[sql_command] & CF_CHANGES_DATA) ? WRITE : READ;
52 #ifndef DBUG_OFF
53 if (THDVAR(thd, exec_time_debug)) {
54 ulonglong t = THDVAR(thd, exec_time_debug);
55@@ -139,11 +165,13 @@
56 SQLCOM_SET_OPTION )) {
57 t = 0;
58 }
59- query_response_time_collect(t);
60+ query_response_time_collect(query_type, t);
61 }
62 else
63 #endif
64- query_response_time_collect(thd->utime_after_query - thd->utime_after_lock);
65+ query_response_time_collect(query_type,
66+ thd->utime_after_query -
67+ thd->utime_after_lock);
68 }
69 }
70
71@@ -172,6 +200,36 @@
72 0,
73 },
74 {
75+ MYSQL_INFORMATION_SCHEMA_PLUGIN,
76+ &query_response_time_info_descriptor,
77+ "QUERY_RESPONSE_TIME_READ",
78+ "Percona and Sergey Vojtovich",
79+ "Query Response Time Distribution INFORMATION_SCHEMA Plugin",
80+ PLUGIN_LICENSE_GPL,
81+ query_response_time_info_init,
82+ query_response_time_info_deinit,
83+ 0x0100,
84+ NULL,
85+ NULL,
86+ (void *)"1.0",
87+ 0,
88+},
89+{
90+ MYSQL_INFORMATION_SCHEMA_PLUGIN,
91+ &query_response_time_info_descriptor,
92+ "QUERY_RESPONSE_TIME_WRITE",
93+ "Percona and Sergey Vojtovich",
94+ "Query Response Time Distribution INFORMATION_SCHEMA Plugin",
95+ PLUGIN_LICENSE_GPL,
96+ query_response_time_info_init,
97+ query_response_time_info_deinit,
98+ 0x0100,
99+ NULL,
100+ NULL,
101+ (void *)"1.0",
102+ 0,
103+},
104+{
105 MYSQL_AUDIT_PLUGIN,
106 &query_response_time_audit_descriptor,
107 "QUERY_RESPONSE_TIME_AUDIT",
108
109=== modified file 'plugin/query_response_time/query_response_time.cc'
110--- plugin/query_response_time/query_response_time.cc 2014-09-25 06:33:00 +0000
111+++ plugin/query_response_time/query_response_time.cc 2015-02-04 16:22:40 +0000
112@@ -170,17 +170,17 @@
113 {
114 my_atomic_rwlock_destroy(&time_collector_lock);
115 }
116- uint32 count(uint index)
117+ uint32 count(QUERY_TYPE type, uint index)
118 {
119 my_atomic_rwlock_rdlock(&time_collector_lock);
120- uint32 result= my_atomic_load32((int32*)&m_count[index]);
121+ uint32 result= my_atomic_load32((int32*)&m_count[type][index]);
122 my_atomic_rwlock_rdunlock(&time_collector_lock);
123 return result;
124 }
125- uint64 total(uint index)
126+ uint64 total(QUERY_TYPE type, uint index)
127 {
128 my_atomic_rwlock_rdlock(&time_collector_lock);
129- uint64 result= my_atomic_load64((int64*)&m_total[index]);
130+ uint64 result= my_atomic_load64((int64*)&m_total[type][index]);
131 my_atomic_rwlock_rdunlock(&time_collector_lock);
132 return result;
133 }
134@@ -192,7 +192,7 @@
135 memset((void*)&m_total,0,sizeof(m_total));
136 my_atomic_rwlock_wrunlock(&time_collector_lock);
137 }
138- void collect(uint64 time)
139+ void collect(QUERY_TYPE type, uint64 time)
140 {
141 int i= 0;
142 for(int count= m_utility->bound_count(); count > i; ++i)
143@@ -200,8 +200,10 @@
144 if(m_utility->bound(i) > time)
145 {
146 my_atomic_rwlock_wrlock(&time_collector_lock);
147- my_atomic_add32((int32*)(&m_count[i]), 1);
148- my_atomic_add64((int64*)(&m_total[i]), time);
149+ my_atomic_add32((int32*)(&m_count[0][i]), 1);
150+ my_atomic_add64((int64*)(&m_total[0][i]), time);
151+ my_atomic_add32((int32*)(&m_count[type][i]), 1);
152+ my_atomic_add64((int64*)(&m_total[type][i]), time);
153 my_atomic_rwlock_wrunlock(&time_collector_lock);
154 break;
155 }
156@@ -209,12 +211,18 @@
157 }
158 private:
159 utility* m_utility;
160- /* The lock for atomic operations on m_count and m_total. Only actually
161- used on architectures that do not have atomic implementation of atomic
162- operations. */
163+ /* The lock for atomic operations on
164+ m_count, m_total, m_r_count, m_r_total, m_w_count, m_w_total.
165+ Only actually used on architectures that do not have atomic
166+ implementation of atomic operations. */
167 my_atomic_rwlock_t time_collector_lock;
168- uint32 m_count[OVERALL_POWER_COUNT + 1];
169- uint64 m_total[OVERALL_POWER_COUNT + 1];
170+ /*
171+ The first row is for overall statistics,
172+ the second row is for 'read' queries,
173+ the third row is for 'write' queries.
174+ */
175+ uint32 m_count[3][OVERALL_POWER_COUNT + 1];
176+ uint64 m_total[3][OVERALL_POWER_COUNT + 1];
177 };
178
179 class collector
180@@ -231,7 +239,9 @@
181 m_utility.setup(opt_query_response_time_range_base);
182 m_time.flush();
183 }
184- int fill(THD* thd, TABLE_LIST *tables, COND *cond)
185+ int fill(QUERY_TYPE type,
186+ THD* thd,
187+ TABLE_LIST *tables, COND *cond)
188 {
189 DBUG_ENTER("fill_schema_query_response_time");
190 TABLE *table= static_cast<TABLE*>(tables->table);
191@@ -250,10 +260,10 @@
192 else
193 {
194 print_time(time, sizeof(time), TIME_STRING_FORMAT, this->bound(i));
195- print_time(total, sizeof(total), TOTAL_STRING_FORMAT, this->total(i));
196+ print_time(total, sizeof(total), TOTAL_STRING_FORMAT, this->total(type, i));
197 }
198 fields[0]->store(time,strlen(time),system_charset_info);
199- fields[1]->store(this->count(i));
200+ fields[1]->store(this->count(type, i));
201 fields[2]->store(total,strlen(total),system_charset_info);
202 if (schema_table_store_record(thd, table))
203 {
204@@ -262,9 +272,9 @@
205 }
206 DBUG_RETURN(0);
207 }
208- void collect(ulonglong time)
209+ void collect(QUERY_TYPE type, ulonglong time)
210 {
211- m_time.collect(time);
212+ m_time.collect(type, time);
213 }
214 uint bound_count() const
215 {
216@@ -274,13 +284,13 @@
217 {
218 return m_utility.bound(index);
219 }
220- ulonglong count(uint index)
221+ ulonglong count(QUERY_TYPE type, uint index)
222 {
223- return m_time.count(index);
224+ return m_time.count(type, index);
225 }
226- ulonglong total(uint index)
227+ ulonglong total(QUERY_TYPE type, uint index)
228 {
229- return m_time.total(index);
230+ return m_time.total(type, index);
231 }
232 private:
233 utility m_utility;
234@@ -304,12 +314,23 @@
235 {
236 query_response_time::g_collector.flush();
237 }
238-void query_response_time_collect(ulonglong query_time)
239+
240+void query_response_time_collect(QUERY_TYPE type,
241+ ulonglong query_time)
242 {
243- query_response_time::g_collector.collect(query_time);
244+ query_response_time::g_collector.collect(type, query_time);
245 }
246
247 int query_response_time_fill(THD* thd, TABLE_LIST *tables, COND *cond)
248 {
249- return query_response_time::g_collector.fill(thd,tables,cond);
250+ QUERY_TYPE query_type= ANY;
251+ if (!strncmp(tables->table->alias,
252+ "QUERY_RESPONSE_TIME_READ",
253+ sizeof("QUERY_RESPONSE_TIME_READ") - 1))
254+ query_type= READ;
255+ else if (!strncmp(tables->table->alias,
256+ "QUERY_RESPONSE_TIME_WRITE",
257+ sizeof("QUERY_RESPONSE_TIME_WRITE") - 1))
258+ query_type= WRITE;
259+ return query_response_time::g_collector.fill(query_type, thd, tables, cond);
260 }
261
262=== modified file 'plugin/query_response_time/query_response_time.h'
263--- plugin/query_response_time/query_response_time.h 2014-09-25 06:33:00 +0000
264+++ plugin/query_response_time/query_response_time.h 2015-02-04 16:22:40 +0000
265@@ -66,6 +66,13 @@
266 MY_MAX( (QRT_TOTAL_STRING_POSITIVE_POWER_LENGTH + 1 /* '.' */ + 6 /*QRT_TOTAL_STRING_NEGATIVE_POWER_LENGTH*/), \
267 (sizeof(QRT_TIME_OVERFLOW) - 1) )
268
269+enum QUERY_TYPE
270+{
271+ ANY= 0,
272+ READ= 1,
273+ WRITE= 2
274+};
275+
276 extern ST_SCHEMA_TABLE query_response_time_table;
277
278 typedef class Item COND;
279@@ -73,7 +80,7 @@
280 extern void query_response_time_init ();
281 extern void query_response_time_free ();
282 extern void query_response_time_flush ();
283-extern void query_response_time_collect(ulonglong query_time);
284+extern void query_response_time_collect(QUERY_TYPE type, ulonglong query_time);
285 extern int query_response_time_fill (THD* thd, TABLE_LIST *tables, COND *cond);
286
287 extern ulong opt_query_response_time_range_base;
288
289=== modified file 'plugin/query_response_time/tests/mtr/basic.result'
290--- plugin/query_response_time/tests/mtr/basic.result 2014-09-25 06:33:00 +0000
291+++ plugin/query_response_time/tests/mtr/basic.result 2015-02-04 16:22:40 +0000
292@@ -23,6 +23,18 @@
293 PLUGIN_AUTHOR Percona and Sergey Vojtovich
294 PLUGIN_DESCRIPTION Query Response Time Distribution INFORMATION_SCHEMA Plugin
295 PLUGIN_LICENSE GPL
296+PLUGIN_NAME QUERY_RESPONSE_TIME_READ
297+PLUGIN_VERSION 1.0
298+PLUGIN_TYPE INFORMATION SCHEMA
299+PLUGIN_AUTHOR Percona and Sergey Vojtovich
300+PLUGIN_DESCRIPTION Query Response Time Distribution INFORMATION_SCHEMA Plugin
301+PLUGIN_LICENSE GPL
302+PLUGIN_NAME QUERY_RESPONSE_TIME_WRITE
303+PLUGIN_VERSION 1.0
304+PLUGIN_TYPE INFORMATION SCHEMA
305+PLUGIN_AUTHOR Percona and Sergey Vojtovich
306+PLUGIN_DESCRIPTION Query Response Time Distribution INFORMATION_SCHEMA Plugin
307+PLUGIN_LICENSE GPL
308 SET GLOBAL QUERY_RESPONSE_TIME_STATS=1;
309 SELECT 1;
310 1
311
312=== added file 'plugin/query_response_time/tests/mtr/query_response_time-rw-begin.inc'
313--- plugin/query_response_time/tests/mtr/query_response_time-rw-begin.inc 1970-01-01 00:00:00 +0000
314+++ plugin/query_response_time/tests/mtr/query_response_time-rw-begin.inc 2015-02-04 16:22:40 +0000
315@@ -0,0 +1,16 @@
316+--disable_query_log
317+--disable_result_log
318+SET GLOBAL QUERY_RESPONSE_TIME_STATS = 0;
319+SET GLOBAL QUERY_RESPONSE_TIME_FLUSH = 1;
320+SET SESSION QUERY_RESPONSE_TIME_EXEC_TIME_DEBUG = 500000;
321+--enable_query_log
322+--enable_result_log
323+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
324+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
325+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
326+--disable_query_log
327+--disable_result_log
328+SET GLOBAL QUERY_RESPONSE_TIME_STATS = 1;
329+--enable_query_log
330+--enable_result_log
331+--echo ------------------Test body begin--------------------
332
333=== added file 'plugin/query_response_time/tests/mtr/query_response_time-rw-end.inc'
334--- plugin/query_response_time/tests/mtr/query_response_time-rw-end.inc 1970-01-01 00:00:00 +0000
335+++ plugin/query_response_time/tests/mtr/query_response_time-rw-end.inc 2015-02-04 16:22:40 +0000
336@@ -0,0 +1,10 @@
337+--echo ------------------Test body end----------------------
338+--disable_query_log
339+--disable_result_log
340+SET GLOBAL QUERY_RESPONSE_TIME_STATS = 0;
341+SET SESSION QUERY_RESPONSE_TIME_EXEC_TIME_DEBUG = DEFAULT;
342+--enable_query_log
343+--enable_result_log
344+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
345+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
346+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
347
348=== added file 'plugin/query_response_time/tests/mtr/query_response_time-rw.result'
349--- plugin/query_response_time/tests/mtr/query_response_time-rw.result 1970-01-01 00:00:00 +0000
350+++ plugin/query_response_time/tests/mtr/query_response_time-rw.result 2015-02-04 16:22:40 +0000
351@@ -0,0 +1,765 @@
352+CREATE FUNCTION DML_FUNC()
353+RETURNS INT
354+BEGIN
355+INSERT INTO t1 (b) VALUES (1), (2);
356+UPDATE t1 SET b = 1;
357+RETURN 1;
358+END|
359+CREATE PROCEDURE NESTED_PROC()
360+BEGIN
361+SELECT DML_FUNC();
362+END|
363+SET default_storage_engine=InnoDB;
364+
365+============================
366+= Test for simple DML and DDL
367+============================
368+
369+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
370+TIME COUNT TOTAL
371+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
372+TIME COUNT TOTAL
373+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
374+TIME COUNT TOTAL
375+------------------Test body begin--------------------
376+CREATE TABLE t1 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
377+b INT UNSIGNED NOT NULL DEFAULT 0);
378+INSERT INTO t1 (b) VALUES (1), (2);
379+UPDATE t1 SET b = 1;
380+SELECT * FROM t1;
381+a b
382+1 1
383+2 1
384+DELETE FROM t1;
385+ALTER TABLE t1 ADD COLUMN (c INT);
386+DROP TABLE t1;
387+------------------Test body end----------------------
388+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
389+TIME COUNT TOTAL
390+ 0.000001 1 0.000000
391+ 1.000000 7 3.500000
392+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
393+TIME COUNT TOTAL
394+ 0.000001 1 0.000000
395+ 1.000000 1 0.500000
396+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
397+TIME COUNT TOTAL
398+ 1.000000 6 3.000000
399+CREATE TABLE t1 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
400+b INT(10) UNSIGNED NOT NULL DEFAULT 0);
401+
402+============================
403+= Test for SELECT+DML
404+============================
405+
406+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
407+TIME COUNT TOTAL
408+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
409+TIME COUNT TOTAL
410+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
411+TIME COUNT TOTAL
412+------------------Test body begin--------------------
413+SELECT DML_FUNC();
414+DML_FUNC()
415+1
416+------------------Test body end----------------------
417+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
418+TIME COUNT TOTAL
419+ 0.000001 1 0.000000
420+ 1.000000 3 1.500000
421+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
422+TIME COUNT TOTAL
423+ 0.000001 1 0.000000
424+ 1.000000 1 0.500000
425+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
426+TIME COUNT TOTAL
427+ 1.000000 2 1.000000
428+
429+============================
430+= Test for nested calls
431+============================
432+
433+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
434+TIME COUNT TOTAL
435+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
436+TIME COUNT TOTAL
437+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
438+TIME COUNT TOTAL
439+------------------Test body begin--------------------
440+CALL NESTED_PROC();
441+DML_FUNC()
442+1
443+------------------Test body end----------------------
444+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
445+TIME COUNT TOTAL
446+ 0.000001 1 0.000000
447+ 1.000000 4 2.000000
448+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
449+TIME COUNT TOTAL
450+ 0.000001 1 0.000000
451+ 1.000000 2 1.000000
452+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
453+TIME COUNT TOTAL
454+ 1.000000 2 1.000000
455+
456+============================
457+= Test for 'PREPARE'
458+============================
459+
460+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
461+TIME COUNT TOTAL
462+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
463+TIME COUNT TOTAL
464+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
465+TIME COUNT TOTAL
466+------------------Test body begin--------------------
467+PREPARE rw_stmt FROM 'DELETE FROM t1';
468+PREPARE ro_stmt FROM 'SELECT * FROM t1';
469+PREPARE select_dml_stmt FROM 'SELECT DML_FUNC()';
470+PREPARE nested_call_stmt FROM 'CALL NESTED_PROC()';
471+------------------Test body end----------------------
472+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
473+TIME COUNT TOTAL
474+ 0.000001 1 0.000000
475+ 1.000000 4 2.000000
476+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
477+TIME COUNT TOTAL
478+ 0.000001 1 0.000000
479+ 1.000000 4 2.000000
480+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
481+TIME COUNT TOTAL
482+
483+============================
484+= Test for 'EXECUTE'
485+============================
486+
487+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
488+TIME COUNT TOTAL
489+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
490+TIME COUNT TOTAL
491+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
492+TIME COUNT TOTAL
493+------------------Test body begin--------------------
494+EXECUTE rw_stmt;
495+EXECUTE ro_stmt;
496+a b
497+EXECUTE select_dml_stmt;
498+DML_FUNC()
499+1
500+EXECUTE nested_call_stmt;
501+DML_FUNC()
502+1
503+------------------Test body end----------------------
504+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
505+TIME COUNT TOTAL
506+ 0.000001 1 0.000000
507+ 1.000000 9 4.500000
508+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
509+TIME COUNT TOTAL
510+ 0.000001 1 0.000000
511+ 1.000000 4 2.000000
512+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
513+TIME COUNT TOTAL
514+ 1.000000 5 2.500000
515+
516+============================
517+= Test for 'DEALLOCATE PREPARE'
518+============================
519+
520+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
521+TIME COUNT TOTAL
522+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
523+TIME COUNT TOTAL
524+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
525+TIME COUNT TOTAL
526+------------------Test body begin--------------------
527+DEALLOCATE PREPARE rw_stmt;
528+DEALLOCATE PREPARE ro_stmt;
529+DEALLOCATE PREPARE select_dml_stmt;
530+DEALLOCATE PREPARE nested_call_stmt;
531+------------------Test body end----------------------
532+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
533+TIME COUNT TOTAL
534+ 0.000001 1 0.000000
535+ 1.000000 4 2.000000
536+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
537+TIME COUNT TOTAL
538+ 0.000001 1 0.000000
539+ 1.000000 4 2.000000
540+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
541+TIME COUNT TOTAL
542+
543+============================
544+= Test for transactions
545+============================
546+
547+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
548+TIME COUNT TOTAL
549+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
550+TIME COUNT TOTAL
551+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
552+TIME COUNT TOTAL
553+------------------Test body begin--------------------
554+BEGIN;
555+SELECT * FROM t1;
556+a b
557+5 1
558+6 1
559+7 1
560+8 1
561+COMMIT;
562+------------------Test body end----------------------
563+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
564+TIME COUNT TOTAL
565+ 0.000001 1 0.000000
566+ 1.000000 3 1.500000
567+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
568+TIME COUNT TOTAL
569+ 0.000001 1 0.000000
570+ 1.000000 3 1.500000
571+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
572+TIME COUNT TOTAL
573+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
574+TIME COUNT TOTAL
575+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
576+TIME COUNT TOTAL
577+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
578+TIME COUNT TOTAL
579+------------------Test body begin--------------------
580+BEGIN;
581+INSERT INTO t1 (b) VALUES (1), (2);
582+UPDATE t1 SET b = 1;
583+SELECT * FROM t1;
584+a b
585+5 1
586+6 1
587+7 1
588+8 1
589+9 1
590+10 1
591+DELETE FROM t1;
592+COMMIT;
593+------------------Test body end----------------------
594+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
595+TIME COUNT TOTAL
596+ 0.000001 1 0.000000
597+ 1.000000 6 3.000000
598+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
599+TIME COUNT TOTAL
600+ 0.000001 1 0.000000
601+ 1.000000 3 1.500000
602+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
603+TIME COUNT TOTAL
604+ 1.000000 3 1.500000
605+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
606+TIME COUNT TOTAL
607+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
608+TIME COUNT TOTAL
609+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
610+TIME COUNT TOTAL
611+------------------Test body begin--------------------
612+BEGIN;
613+SELECT DML_FUNC();
614+DML_FUNC()
615+1
616+CALL NESTED_PROC();
617+DML_FUNC()
618+1
619+COMMIT;
620+------------------Test body end----------------------
621+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
622+TIME COUNT TOTAL
623+ 0.000001 1 0.000000
624+ 1.000000 9 4.500000
625+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
626+TIME COUNT TOTAL
627+ 0.000001 1 0.000000
628+ 1.000000 5 2.500000
629+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
630+TIME COUNT TOTAL
631+ 1.000000 4 2.000000
632+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
633+TIME COUNT TOTAL
634+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
635+TIME COUNT TOTAL
636+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
637+TIME COUNT TOTAL
638+------------------Test body begin--------------------
639+BEGIN;
640+INSERT INTO t1 (b) VALUES (1), (2);
641+UPDATE t1 SET b = 1;
642+ROLLBACK;
643+------------------Test body end----------------------
644+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
645+TIME COUNT TOTAL
646+ 0.000001 1 0.000000
647+ 1.000000 4 2.000000
648+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
649+TIME COUNT TOTAL
650+ 0.000001 1 0.000000
651+ 1.000000 2 1.000000
652+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
653+TIME COUNT TOTAL
654+ 1.000000 2 1.000000
655+
656+============================
657+= Test for implicit commit
658+============================
659+
660+SET autocommit = 0;
661+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
662+TIME COUNT TOTAL
663+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
664+TIME COUNT TOTAL
665+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
666+TIME COUNT TOTAL
667+------------------Test body begin--------------------
668+INSERT INTO t1 (b) VALUES (1), (2);
669+CREATE INDEX ab ON t1 (a, b);
670+------------------Test body end----------------------
671+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
672+TIME COUNT TOTAL
673+ 0.000001 1 0.000000
674+ 1.000000 2 1.000000
675+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
676+TIME COUNT TOTAL
677+ 0.000001 1 0.000000
678+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
679+TIME COUNT TOTAL
680+ 1.000000 2 1.000000
681+SET autocommit = 1;
682+
683+============================
684+= Test for trigger
685+============================
686+
687+CREATE TABLE t2 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
688+b INT UNSIGNED NOT NULL DEFAULT 0);
689+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
690+TIME COUNT TOTAL
691+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
692+TIME COUNT TOTAL
693+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
694+TIME COUNT TOTAL
695+------------------Test body begin--------------------
696+CREATE TRIGGER test_trigger BEFORE INSERT ON t1
697+FOR EACH ROW
698+BEGIN
699+INSERT INTO t2 SET b = NEW.b;
700+INSERT INTO t2 SET b = NEW.b;
701+END;
702+|
703+------------------Test body end----------------------
704+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
705+TIME COUNT TOTAL
706+ 0.000001 1 0.000000
707+ 1.000000 1 0.500000
708+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
709+TIME COUNT TOTAL
710+ 0.000001 1 0.000000
711+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
712+TIME COUNT TOTAL
713+ 1.000000 1 0.500000
714+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
715+TIME COUNT TOTAL
716+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
717+TIME COUNT TOTAL
718+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
719+TIME COUNT TOTAL
720+------------------Test body begin--------------------
721+INSERT INTO t1 (b) VALUES (1), (2);
722+------------------Test body end----------------------
723+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
724+TIME COUNT TOTAL
725+ 0.000001 1 0.000000
726+ 1.000000 5 2.500000
727+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
728+TIME COUNT TOTAL
729+ 0.000001 1 0.000000
730+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
731+TIME COUNT TOTAL
732+ 1.000000 5 2.500000
733+DROP TABLE t1;
734+DROP TABLE t2;
735+SET default_storage_engine=InnoDB;
736+SET default_storage_engine=MyISAM;
737+
738+==========================
739+= Test for Innodb engine
740+==========================
741+
742+============================
743+= Test for simple DML and DDL
744+============================
745+
746+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
747+TIME COUNT TOTAL
748+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
749+TIME COUNT TOTAL
750+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
751+TIME COUNT TOTAL
752+------------------Test body begin--------------------
753+CREATE TABLE t1 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
754+b INT UNSIGNED NOT NULL DEFAULT 0);
755+INSERT INTO t1 (b) VALUES (1), (2);
756+UPDATE t1 SET b = 1;
757+SELECT * FROM t1;
758+a b
759+1 1
760+2 1
761+DELETE FROM t1;
762+ALTER TABLE t1 ADD COLUMN (c INT);
763+DROP TABLE t1;
764+------------------Test body end----------------------
765+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
766+TIME COUNT TOTAL
767+ 0.000001 1 0.000000
768+ 1.000000 7 3.500000
769+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
770+TIME COUNT TOTAL
771+ 0.000001 1 0.000000
772+ 1.000000 1 0.500000
773+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
774+TIME COUNT TOTAL
775+ 1.000000 6 3.000000
776+CREATE TABLE t1 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
777+b INT(10) UNSIGNED NOT NULL DEFAULT 0);
778+
779+============================
780+= Test for SELECT+DML
781+============================
782+
783+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
784+TIME COUNT TOTAL
785+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
786+TIME COUNT TOTAL
787+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
788+TIME COUNT TOTAL
789+------------------Test body begin--------------------
790+SELECT DML_FUNC();
791+DML_FUNC()
792+1
793+------------------Test body end----------------------
794+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
795+TIME COUNT TOTAL
796+ 0.000001 1 0.000000
797+ 1.000000 3 1.500000
798+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
799+TIME COUNT TOTAL
800+ 0.000001 1 0.000000
801+ 1.000000 1 0.500000
802+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
803+TIME COUNT TOTAL
804+ 1.000000 2 1.000000
805+
806+============================
807+= Test for nested calls
808+============================
809+
810+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
811+TIME COUNT TOTAL
812+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
813+TIME COUNT TOTAL
814+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
815+TIME COUNT TOTAL
816+------------------Test body begin--------------------
817+CALL NESTED_PROC();
818+DML_FUNC()
819+1
820+------------------Test body end----------------------
821+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
822+TIME COUNT TOTAL
823+ 0.000001 1 0.000000
824+ 1.000000 4 2.000000
825+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
826+TIME COUNT TOTAL
827+ 0.000001 1 0.000000
828+ 1.000000 2 1.000000
829+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
830+TIME COUNT TOTAL
831+ 1.000000 2 1.000000
832+
833+============================
834+= Test for 'PREPARE'
835+============================
836+
837+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
838+TIME COUNT TOTAL
839+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
840+TIME COUNT TOTAL
841+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
842+TIME COUNT TOTAL
843+------------------Test body begin--------------------
844+PREPARE rw_stmt FROM 'DELETE FROM t1';
845+PREPARE ro_stmt FROM 'SELECT * FROM t1';
846+PREPARE select_dml_stmt FROM 'SELECT DML_FUNC()';
847+PREPARE nested_call_stmt FROM 'CALL NESTED_PROC()';
848+------------------Test body end----------------------
849+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
850+TIME COUNT TOTAL
851+ 0.000001 1 0.000000
852+ 1.000000 4 2.000000
853+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
854+TIME COUNT TOTAL
855+ 0.000001 1 0.000000
856+ 1.000000 4 2.000000
857+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
858+TIME COUNT TOTAL
859+
860+============================
861+= Test for 'EXECUTE'
862+============================
863+
864+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
865+TIME COUNT TOTAL
866+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
867+TIME COUNT TOTAL
868+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
869+TIME COUNT TOTAL
870+------------------Test body begin--------------------
871+EXECUTE rw_stmt;
872+EXECUTE ro_stmt;
873+a b
874+EXECUTE select_dml_stmt;
875+DML_FUNC()
876+1
877+EXECUTE nested_call_stmt;
878+DML_FUNC()
879+1
880+------------------Test body end----------------------
881+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
882+TIME COUNT TOTAL
883+ 0.000001 1 0.000000
884+ 1.000000 9 4.500000
885+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
886+TIME COUNT TOTAL
887+ 0.000001 1 0.000000
888+ 1.000000 4 2.000000
889+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
890+TIME COUNT TOTAL
891+ 1.000000 5 2.500000
892+
893+============================
894+= Test for 'DEALLOCATE PREPARE'
895+============================
896+
897+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
898+TIME COUNT TOTAL
899+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
900+TIME COUNT TOTAL
901+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
902+TIME COUNT TOTAL
903+------------------Test body begin--------------------
904+DEALLOCATE PREPARE rw_stmt;
905+DEALLOCATE PREPARE ro_stmt;
906+DEALLOCATE PREPARE select_dml_stmt;
907+DEALLOCATE PREPARE nested_call_stmt;
908+------------------Test body end----------------------
909+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
910+TIME COUNT TOTAL
911+ 0.000001 1 0.000000
912+ 1.000000 4 2.000000
913+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
914+TIME COUNT TOTAL
915+ 0.000001 1 0.000000
916+ 1.000000 4 2.000000
917+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
918+TIME COUNT TOTAL
919+
920+============================
921+= Test for transactions
922+============================
923+
924+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
925+TIME COUNT TOTAL
926+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
927+TIME COUNT TOTAL
928+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
929+TIME COUNT TOTAL
930+------------------Test body begin--------------------
931+BEGIN;
932+SELECT * FROM t1;
933+a b
934+5 1
935+6 1
936+7 1
937+8 1
938+COMMIT;
939+------------------Test body end----------------------
940+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
941+TIME COUNT TOTAL
942+ 0.000001 1 0.000000
943+ 1.000000 3 1.500000
944+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
945+TIME COUNT TOTAL
946+ 0.000001 1 0.000000
947+ 1.000000 3 1.500000
948+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
949+TIME COUNT TOTAL
950+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
951+TIME COUNT TOTAL
952+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
953+TIME COUNT TOTAL
954+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
955+TIME COUNT TOTAL
956+------------------Test body begin--------------------
957+BEGIN;
958+INSERT INTO t1 (b) VALUES (1), (2);
959+UPDATE t1 SET b = 1;
960+SELECT * FROM t1;
961+a b
962+5 1
963+6 1
964+7 1
965+8 1
966+9 1
967+10 1
968+DELETE FROM t1;
969+COMMIT;
970+------------------Test body end----------------------
971+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
972+TIME COUNT TOTAL
973+ 0.000001 1 0.000000
974+ 1.000000 6 3.000000
975+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
976+TIME COUNT TOTAL
977+ 0.000001 1 0.000000
978+ 1.000000 3 1.500000
979+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
980+TIME COUNT TOTAL
981+ 1.000000 3 1.500000
982+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
983+TIME COUNT TOTAL
984+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
985+TIME COUNT TOTAL
986+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
987+TIME COUNT TOTAL
988+------------------Test body begin--------------------
989+BEGIN;
990+SELECT DML_FUNC();
991+DML_FUNC()
992+1
993+CALL NESTED_PROC();
994+DML_FUNC()
995+1
996+COMMIT;
997+------------------Test body end----------------------
998+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
999+TIME COUNT TOTAL
1000+ 0.000001 1 0.000000
1001+ 1.000000 9 4.500000
1002+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1003+TIME COUNT TOTAL
1004+ 0.000001 1 0.000000
1005+ 1.000000 5 2.500000
1006+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1007+TIME COUNT TOTAL
1008+ 1.000000 4 2.000000
1009+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
1010+TIME COUNT TOTAL
1011+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1012+TIME COUNT TOTAL
1013+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1014+TIME COUNT TOTAL
1015+------------------Test body begin--------------------
1016+BEGIN;
1017+INSERT INTO t1 (b) VALUES (1), (2);
1018+UPDATE t1 SET b = 1;
1019+ROLLBACK;
1020+Warnings:
1021+Warning 1196 Some non-transactional changed tables couldn't be rolled back
1022+------------------Test body end----------------------
1023+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
1024+TIME COUNT TOTAL
1025+ 0.000001 1 0.000000
1026+ 1.000000 5 2.500000
1027+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1028+TIME COUNT TOTAL
1029+ 0.000001 1 0.000000
1030+ 1.000000 3 1.500000
1031+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1032+TIME COUNT TOTAL
1033+ 1.000000 2 1.000000
1034+
1035+============================
1036+= Test for implicit commit
1037+============================
1038+
1039+SET autocommit = 0;
1040+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
1041+TIME COUNT TOTAL
1042+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1043+TIME COUNT TOTAL
1044+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1045+TIME COUNT TOTAL
1046+------------------Test body begin--------------------
1047+INSERT INTO t1 (b) VALUES (1), (2);
1048+CREATE INDEX ab ON t1 (a, b);
1049+------------------Test body end----------------------
1050+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
1051+TIME COUNT TOTAL
1052+ 0.000001 1 0.000000
1053+ 1.000000 2 1.000000
1054+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1055+TIME COUNT TOTAL
1056+ 0.000001 1 0.000000
1057+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1058+TIME COUNT TOTAL
1059+ 1.000000 2 1.000000
1060+SET autocommit = 1;
1061+
1062+============================
1063+= Test for trigger
1064+============================
1065+
1066+CREATE TABLE t2 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
1067+b INT UNSIGNED NOT NULL DEFAULT 0);
1068+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
1069+TIME COUNT TOTAL
1070+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1071+TIME COUNT TOTAL
1072+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1073+TIME COUNT TOTAL
1074+------------------Test body begin--------------------
1075+CREATE TRIGGER test_trigger BEFORE INSERT ON t1
1076+FOR EACH ROW
1077+BEGIN
1078+INSERT INTO t2 SET b = NEW.b;
1079+INSERT INTO t2 SET b = NEW.b;
1080+END;
1081+|
1082+------------------Test body end----------------------
1083+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
1084+TIME COUNT TOTAL
1085+ 0.000001 1 0.000000
1086+ 1.000000 1 0.500000
1087+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1088+TIME COUNT TOTAL
1089+ 0.000001 1 0.000000
1090+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1091+TIME COUNT TOTAL
1092+ 1.000000 1 0.500000
1093+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
1094+TIME COUNT TOTAL
1095+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1096+TIME COUNT TOTAL
1097+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1098+TIME COUNT TOTAL
1099+------------------Test body begin--------------------
1100+INSERT INTO t1 (b) VALUES (1), (2);
1101+------------------Test body end----------------------
1102+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME WHERE count != 0;
1103+TIME COUNT TOTAL
1104+ 0.000001 1 0.000000
1105+ 1.000000 5 2.500000
1106+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_READ WHERE count != 0;
1107+TIME COUNT TOTAL
1108+ 0.000001 1 0.000000
1109+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME_WRITE WHERE count != 0;
1110+TIME COUNT TOTAL
1111+ 1.000000 5 2.500000
1112+DROP TABLE t1;
1113+DROP TABLE t2;
1114+SET default_storage_engine=default;
1115+DROP FUNCTION DML_FUNC;
1116+DROP PROCEDURE NESTED_PROC;
1117
1118=== added file 'plugin/query_response_time/tests/mtr/query_response_time-rw.test'
1119--- plugin/query_response_time/tests/mtr/query_response_time-rw.test 1970-01-01 00:00:00 +0000
1120+++ plugin/query_response_time/tests/mtr/query_response_time-rw.test 2015-02-04 16:22:40 +0000
1121@@ -0,0 +1,201 @@
1122+--source include/have_query_response_time_plugin.inc
1123+--source include/have_debug.inc
1124+
1125+# The file with expected results fits only to a run without
1126+# ps-protocol/sp-protocol/cursor-protocol/view-protocol.
1127+if (`SELECT $PS_PROTOCOL + $SP_PROTOCOL + $CURSOR_PROTOCOL
1128+ + $VIEW_PROTOCOL > 0`)
1129+{
1130+ --skip Test requires: ps-protocol/sp-protocol/cursor-protocol/view-protocol disabled
1131+}
1132+
1133+--delimiter |
1134+
1135+CREATE FUNCTION DML_FUNC()
1136+RETURNS INT
1137+BEGIN
1138+ INSERT INTO t1 (b) VALUES (1), (2);
1139+ UPDATE t1 SET b = 1;
1140+ RETURN 1;
1141+END|
1142+
1143+CREATE PROCEDURE NESTED_PROC()
1144+BEGIN
1145+ SELECT DML_FUNC();
1146+END|
1147+
1148+--delimiter ;
1149+
1150+--let $i=2
1151+
1152+while ($i)
1153+{
1154+
1155+ SET default_storage_engine=InnoDB;
1156+ if ($i==1)
1157+ {
1158+ SET default_storage_engine=MyISAM;
1159+ }
1160+
1161+ if ($i==0)
1162+ {
1163+ --echo
1164+ --echo ==========================
1165+ --echo = Test for MyISAM engine
1166+ --echo ==========================
1167+ --echo
1168+ }
1169+ if ($i==1)
1170+ {
1171+ --echo
1172+ --echo ==========================
1173+ --echo = Test for Innodb engine
1174+ --echo ==========================
1175+ }
1176+
1177+ --echo
1178+ --echo ============================
1179+ --echo = Test for simple DML and DDL
1180+ --echo ============================
1181+ --echo
1182+ --source query_response_time-rw-begin.inc
1183+ CREATE TABLE t1 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
1184+ b INT UNSIGNED NOT NULL DEFAULT 0);
1185+ INSERT INTO t1 (b) VALUES (1), (2);
1186+ UPDATE t1 SET b = 1;
1187+ SELECT * FROM t1;
1188+ DELETE FROM t1;
1189+ ALTER TABLE t1 ADD COLUMN (c INT);
1190+ DROP TABLE t1;
1191+ --source query_response_time-rw-end.inc
1192+
1193+ CREATE TABLE t1 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
1194+ b INT(10) UNSIGNED NOT NULL DEFAULT 0);
1195+ --echo
1196+ --echo ============================
1197+ --echo = Test for SELECT+DML
1198+ --echo ============================
1199+ --echo
1200+ --source query_response_time-rw-begin.inc
1201+ SELECT DML_FUNC();
1202+ --source query_response_time-rw-end.inc
1203+
1204+ --echo
1205+ --echo ============================
1206+ --echo = Test for nested calls
1207+ --echo ============================
1208+ --echo
1209+ --source query_response_time-rw-begin.inc
1210+ CALL NESTED_PROC();
1211+ --source query_response_time-rw-end.inc
1212+
1213+ --echo
1214+ --echo ============================
1215+ --echo = Test for 'PREPARE'
1216+ --echo ============================
1217+ --echo
1218+ --source query_response_time-rw-begin.inc
1219+ PREPARE rw_stmt FROM 'DELETE FROM t1';
1220+ PREPARE ro_stmt FROM 'SELECT * FROM t1';
1221+ PREPARE select_dml_stmt FROM 'SELECT DML_FUNC()';
1222+ PREPARE nested_call_stmt FROM 'CALL NESTED_PROC()';
1223+ --source query_response_time-rw-end.inc
1224+
1225+ --echo
1226+ --echo ============================
1227+ --echo = Test for 'EXECUTE'
1228+ --echo ============================
1229+ --echo
1230+ --source query_response_time-rw-begin.inc
1231+ EXECUTE rw_stmt;
1232+ EXECUTE ro_stmt;
1233+ EXECUTE select_dml_stmt;
1234+ EXECUTE nested_call_stmt;
1235+ --source query_response_time-rw-end.inc
1236+
1237+ --echo
1238+ --echo ============================
1239+ --echo = Test for 'DEALLOCATE PREPARE'
1240+ --echo ============================
1241+ --echo
1242+ --source query_response_time-rw-begin.inc
1243+ DEALLOCATE PREPARE rw_stmt;
1244+ DEALLOCATE PREPARE ro_stmt;
1245+ DEALLOCATE PREPARE select_dml_stmt;
1246+ DEALLOCATE PREPARE nested_call_stmt;
1247+ --source query_response_time-rw-end.inc
1248+
1249+ --echo
1250+ --echo ============================
1251+ --echo = Test for transactions
1252+ --echo ============================
1253+ --echo
1254+ --source query_response_time-rw-begin.inc
1255+ BEGIN;
1256+ SELECT * FROM t1;
1257+ COMMIT;
1258+ --source query_response_time-rw-end.inc
1259+ --source query_response_time-rw-begin.inc
1260+ BEGIN;
1261+ INSERT INTO t1 (b) VALUES (1), (2);
1262+ UPDATE t1 SET b = 1;
1263+ SELECT * FROM t1;
1264+ DELETE FROM t1;
1265+ COMMIT;
1266+ --source query_response_time-rw-end.inc
1267+ --source query_response_time-rw-begin.inc
1268+ BEGIN;
1269+ SELECT DML_FUNC();
1270+ CALL NESTED_PROC();
1271+ COMMIT;
1272+ --source query_response_time-rw-end.inc
1273+ --source query_response_time-rw-begin.inc
1274+ BEGIN;
1275+ INSERT INTO t1 (b) VALUES (1), (2);
1276+ UPDATE t1 SET b = 1;
1277+ ROLLBACK;
1278+ --source query_response_time-rw-end.inc
1279+
1280+ --echo
1281+ --echo ============================
1282+ --echo = Test for implicit commit
1283+ --echo ============================
1284+ --echo
1285+ SET autocommit = 0;
1286+ --source query_response_time-rw-begin.inc
1287+ INSERT INTO t1 (b) VALUES (1), (2);
1288+ CREATE INDEX ab ON t1 (a, b);
1289+ --source query_response_time-rw-end.inc
1290+ SET autocommit = 1;
1291+
1292+ --echo
1293+ --echo ============================
1294+ --echo = Test for trigger
1295+ --echo ============================
1296+ --echo
1297+ CREATE TABLE t2 (a INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
1298+ b INT UNSIGNED NOT NULL DEFAULT 0);
1299+ --source query_response_time-rw-begin.inc
1300+ --delimiter |
1301+ CREATE TRIGGER test_trigger BEFORE INSERT ON t1
1302+ FOR EACH ROW
1303+ BEGIN
1304+ INSERT INTO t2 SET b = NEW.b;
1305+ INSERT INTO t2 SET b = NEW.b;
1306+ END;
1307+ |
1308+ --delimiter ;
1309+ --source query_response_time-rw-end.inc
1310+ --source query_response_time-rw-begin.inc
1311+ INSERT INTO t1 (b) VALUES (1), (2);
1312+ --source query_response_time-rw-end.inc
1313+
1314+ DROP TABLE t1;
1315+ DROP TABLE t2;
1316+
1317+ --dec $i
1318+}
1319+
1320+SET default_storage_engine=default;
1321+DROP FUNCTION DML_FUNC;
1322+DROP PROCEDURE NESTED_PROC;
1323
1324=== modified file 'sql/sp_instr.cc'
1325--- sql/sp_instr.cc 2014-09-25 07:10:58 +0000
1326+++ sql/sp_instr.cc 2015-02-04 16:22:40 +0000
1327@@ -821,11 +821,21 @@
1328 {
1329 rc= validate_lex_and_execute_core(thd, nextp, false);
1330
1331+ /*
1332+ thd->utime_after_query can be used for counting
1333+ statement execution time (for example in
1334+ query_response_time plugin). thd->update_server_status()
1335+ updates this value but only if function/procedure
1336+ budy has been already executed, if we want to measure
1337+ statement execution time inside function/procedure
1338+ we have to update this value here independent of
1339+ value returned by thd->get_stmt_da()->is_eof().
1340+ */
1341+ thd->update_server_status();
1342+
1343 if (thd->get_stmt_da()->is_eof())
1344 {
1345 /* Finalize server status flags after executing a statement. */
1346- thd->update_server_status();
1347-
1348 thd->protocol->end_statement();
1349 }
1350

Subscribers

People subscribed via source and target branches