Merge lp:~tsarev/percona-server/5.5_fix_bug_716210 into lp:percona-server/5.5

Proposed by Oleg Tsarev on 2011-09-29
Status: Superseded
Proposed branch: lp:~tsarev/percona-server/5.5_fix_bug_716210
Merge into: lp:percona-server/5.5
Diff against target: 752 lines (+523/-92) (has conflicts)
1 file modified
patches/slow_extended.patch (+523/-92)
Text conflict in patches/slow_extended.patch
To merge this branch: bzr merge lp:~tsarev/percona-server/5.5_fix_bug_716210
Reviewer Review Type Date Requested Status
Laurynas Biveinis 2011-09-29 Needs Fixing on 2011-09-30
Alexey Kopytov 2011-09-29 Pending
Review via email: mp+77458@code.launchpad.net

This proposal supersedes a proposal from 2011-09-12.

This proposal has been superseded by a proposal from 2011-10-07.

Description of the change

      * "all statistics variables used in slow_extended.patch and thd->send_row_count and thd->examined_row_count" == SESV (Slow Extended Statistic Variables)

      * Added to class THD (sql/sql_class.h) following methods:
             1) clear_slow_extended - clear SESV
             2) reset_sub_statement_state_slow_extended(Sub_statement_state *backup) - backup SESV to backup area
             3) restore_sub_statement_state_slow_extended(Sub_statement_state *backup) - restore SESV from backup area

      * Added to class Sub_statement_state (sql/sql_class.h) required for correct backup variables

      * Added to class THD (sql/sql_class.h) comments near the SESV with explanations of purpose of variables

      * Added call of clear_slow_extended to THD::init() (required on THD class initialisation and change_user)

      * Fix admin command processing in LOGGER::slow_log_print (sql/loc.cc). Before fix SESV don't clean correctly (because if(!query_length) never was true).
        Explanation:
          1) query and query_length according to comment in sql_class.h always correlated - if query == NULL => query_length == 0, and if query != NULL => query_length != 0
          2) After "if (!query) { ... }" query_lenght always not 0
          3) if (!query_length) (code before my fix) always trye

      * Fixed accoring to code policy code formating in "increment_thd_innodb_stats" (sql/sql_class.cc)

      * Fixed THD::reset_for_next_command (sql/sql_parse.cc) - replace variables cleaning by clear_slow_extended call

      * Fixed bug #716210: add thd->clear_slow_extended() to dispatch_command()
        Explanation: before dispatch_command mysql doesn't call "reset_for_next_command" and SESV inherited from previous query

Clean Jenkins results: http://jenkins.percona.com/view/Percona%20Server%205.5/job/percona-server-5.5-param/137/

To post a comment you must log in.
Laurynas Biveinis (laurynas-biveinis) wrote : Posted in a previous version of this proposal

LGTM provided that Jenkins result are clean

review: Approve
Alexey Kopytov (akopytov) wrote : Posted in a previous version of this proposal

last_errno is not the only variable that has to be reset for admin commands after a failing statement. Most other counters from slow_extended are affected by the same problem.

Here's an test case:

create table t1(a int primary key);
insert into t1 values (1), (2), (3);
insert into t1 select * from t1 order by rand();

The last statement will fail ER_DUP_ENTRY, and the next admin command will have the same Last_errno, Rows_{sent,examined,affected,read}, Bytes_sent, Tmp_tables, Tmp_disk_tables and Tmp_table_sizes.

I'm fairly sure InnoDB stats have the same problem.

Some comments on the test case:

- with use_global_long_query_time=1 do you really need to create a separate connection?
- please replace 1050 with ER_TABLE_EXISTS_ERROR.

review: Needs Fixing

- I am not sure the class Sub_statement_state is the best place to piggyback the backup info too (maybe Alexey can comment on this.) Perhaps a separate struct is needed?
- Please extend the testcase to show that other variables (Rows_{sent,examined,affected,read}, Bytes_sent, Tmp_tables, Tmp_disk_tables and Tmp_table_sizes) are reset correctly, as pointed out by Alexey.

Typos in the comment at 282--294:
1) "write_to_slow _log"
2) s/inited/initialized
3) I'm not sure what "2)" and "3)" in the comment are trying to say.

Lines 313: I'm not sure what "Following Variables innodb_*** (is |should be) different from" is supposed to mean
Lines 324,329: s/collect/collects
Line 335: s/generates/generate
Line 337: s/contain/contains the
Line 346: constify the argument (unless something prevents this)

review: Needs Fixing
Oleg Tsarev (tsarev) wrote :

> - I am not sure the class Sub_statement_state is the best place to piggyback
> the backup info too (maybe Alexey can comment on this.) Perhaps a separate
> struct is needed?

You can look intо:
void THD::reset_sub_statement_state(Sub_statement_state *backup);

This method use Sub_statement_state for backup all required variables.
I just extend it by me variables (as this was in first version of patch).

Of course, I can extract structure to separated Sub_statement_state_slow_extended, but this is overenginnering, no?

> - Please extend the testcase to show that other variables
> (Rows_{sent,examined,affected,read}, Bytes_sent, Tmp_tables, Tmp_disk_tables
> and Tmp_table_sizes) are reset correctly, as pointed out by Alexey.

ACK

>
> Typos in the comment at 282--294:
> 1) "write_to_slow _log"
> 2) s/inited/initialized
> 3) I'm not sure what "2)" and "3)" in the comment are trying to say.

2) and 3) about variable "write_to_slow_log":
  2) write_to_slow_log never changed (changed just on thread start time)
  3) write_to_slow_log should be used in implementation of feature "sampling by query"

>
> Lines 313: I'm not sure what "Following Variables innodb_*** (is |should be)
> different from" is supposed to mean
> Lines 324,329: s/collect/collects
> Line 335: s/generates/generate
> Line 337: s/contain/contains the
> Line 346: constify the argument (unless something prevents this)

> This method use Sub_statement_state for backup all required variables.
> I just extend it by me variables (as this was in first version of patch).
>
> Of course, I can extract structure to separated
> Sub_statement_state_slow_extended, but this is overenginnering, no?

I have looked more carefully, and I see that some of the already-existing Sub_statement_state fields are used for backup too. Now I agree that just extending it is OK.

> > 3) I'm not sure what "2)" and "3)" in the comment are trying to say.
>
> 2) and 3) about variable "write_to_slow_log":
> 2) write_to_slow_log never changed (changed just on thread start time)
> 3) write_to_slow_log should be used in implementation of feature "sampling
> by query"

2) The variable is initialized on the thread startup and remains constant afterwards. This will change when LP #712396 ("log_slow_slave_statements not work on replication threads without RESTART") is implemented.
3) An implementation of LP #688646 ("Make query sampling possible by query") should use it.

152. By Oleg Tsarev on 2011-10-06

extend tests

Unmerged revisions

152. By Oleg Tsarev on 2011-10-06

extend tests

151. By Oleg Tsarev on 2011-09-28

  * "all statistics variables used in slow_extended.patch and thd->send_row_count and thd->examined_row_count" == SESV (Slow Extended Statistic Variables)

  * Added to class THD (sql/sql_class.h) following methods:
         1) clear_slow_extended - clear SESV
         2) reset_sub_statement_state_slow_extended(Sub_statement_state *backup) - backup SESV to backup area
         3) restore_sub_statement_state_slow_extended(Sub_statement_state *backup) - restore SESV from backup area

  * Added to class Sub_statement_state (sql/sql_class.h) required for correct backup variables

  * Added to class THD (sql/sql_class.h) comments near the SESV with explanations of purpose of variables

  * Added call of clear_slow_extended to THD::init() (required on THD class initialisation and change_user)

  * Fix admin command processing in LOGGER::slow_log_print (sql/loc.cc). Before fix SESV don't clean correctly (because if(!query_length) never was true).
    Explanation:
      1) query and query_length according to comment in sql_class.h always correlated - if query == NULL => query_length == 0, and if query != NULL => query_length != 0
      2) After "if (!query) { ... }" query_lenght always not 0
      3) if (!query_length) (code before my fix) always trye

  * Fixed accoring to code policy code formating in "increment_thd_innodb_stats" (sql/sql_class.cc)

  * Fixed THD::reset_for_next_command (sql/sql_parse.cc) - replace variables cleaning by clear_slow_extended call

  * Fixed bug #716210: add thd->clear_slow_extended() to dispatch_command()
    Explanation: before dispatch_command mysql doesn't call "reset_for_next_command" and SESV inherited from previous query

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'patches/slow_extended.patch'
2--- patches/slow_extended.patch 2011-09-28 14:25:37 +0000
3+++ patches/slow_extended.patch 2011-10-06 23:44:24 +0000
4@@ -227,29 +227,16 @@
5 }
6 else
7 {
8-@@ -1239,8 +1255,20 @@
9- query_length= command_name[thd->command].length;
10+@@ -1240,7 +1256,7 @@
11 }
12
13-+ if (!query_length)
14-+ {
15-+ thd->sent_row_count= thd->examined_row_count= 0;
16-+ thd->sent_row_count= 0;
17-+ thd->bytes_sent_old= thd->status_var.bytes_sent;
18-+ thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
19-+ thd->tmp_tables_size= 0;
20-+ thd->innodb_was_used= FALSE;
21-+ thd->query_plan_flags= QPLAN_NONE;
22-+ thd->query_plan_fsort_passes= 0;
23-+ }
24-+
25 for (current_handler= slow_log_handler_list; *current_handler ;)
26 - error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
27 + error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
28 user_host_buff, user_host_len,
29 query_utime, lock_utime, is_command,
30 query, query_length) || error;
31-@@ -2656,12 +2684,13 @@
32+@@ -2656,12 +2672,13 @@
33 TRUE - error occured
34 */
35
36@@ -264,7 +251,7 @@
37 bool error= 0;
38 DBUG_ENTER("MYSQL_QUERY_LOG::write");
39
40-@@ -2683,17 +2712,28 @@
41+@@ -2683,17 +2700,28 @@
42
43 if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
44 {
45@@ -300,9 +287,11 @@
46
47 /* Note that my_b_write() assumes it knows the length for this */
48 if (my_b_write(&log_file, (uchar*) buff, buff_len))
49-@@ -2711,12 +2751,69 @@
50+@@ -2710,13 +2738,71 @@
51+ /* For slow query log */
52 sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
53 sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0);
54++ DBUG_PRINT("info", ("Last_errno: %u", thd->last_errno));
55 if (my_b_printf(&log_file,
56 - "# Query_time: %s Lock_time: %s"
57 - " Rows_sent: %lu Rows_examined: %lu\n",
58@@ -521,22 +510,22 @@
59
60 +extern "C"
61 +void increment_thd_innodb_stats(THD* thd,
62-+ unsigned long long trx_id,
63-+ long io_reads,
64-+ long long io_read,
65-+ long io_reads_wait_timer,
66-+ long lock_que_wait_timer,
67-+ long que_wait_timer,
68-+ long page_access)
69++ unsigned long long trx_id,
70++ long io_reads,
71++ long long io_read,
72++ long io_reads_wait_timer,
73++ long lock_que_wait_timer,
74++ long que_wait_timer,
75++ long page_access)
76 +{
77-+ thd->innodb_was_used = TRUE;
78-+ thd->innodb_trx_id = trx_id;
79-+ thd->innodb_io_reads += io_reads;
80-+ thd->innodb_io_read += io_read;
81-+ thd->innodb_io_reads_wait_timer += io_reads_wait_timer;
82-+ thd->innodb_lock_que_wait_timer += lock_que_wait_timer;
83-+ thd->innodb_innodb_que_wait_timer += que_wait_timer;
84-+ thd->innodb_page_access += page_access;
85++ thd->innodb_was_used= TRUE;
86++ thd->innodb_trx_id= trx_id;
87++ thd->innodb_io_reads+= io_reads;
88++ thd->innodb_io_read+= io_read;
89++ thd->innodb_io_reads_wait_timer+= io_reads_wait_timer;
90++ thd->innodb_lock_que_wait_timer+= lock_que_wait_timer;
91++ thd->innodb_innodb_que_wait_timer+= que_wait_timer;
92++ thd->innodb_page_access+= page_access;
93 +}
94 +
95 +extern "C"
96@@ -562,44 +551,124 @@
97 if (!m_internal_handler)
98 {
99 *cond_hdl= NULL;
100-@@ -3656,6 +3689,12 @@
101+@@ -1201,6 +1234,8 @@
102+ /* Initialize the Debug Sync Facility. See debug_sync.cc. */
103+ debug_sync_init_thread(this);
104+ #endif /* defined(ENABLED_DEBUG_SYNC) */
105++
106++ clear_slow_extended();
107+ }
108+
109+
110+@@ -3647,8 +3682,6 @@
111+ backup->in_sub_stmt= in_sub_stmt;
112+ backup->enable_slow_log= enable_slow_log;
113+ backup->limit_found_rows= limit_found_rows;
114+- backup->examined_row_count= examined_row_count;
115+- backup->sent_row_count= sent_row_count;
116+ backup->cuted_fields= cuted_fields;
117+ backup->client_capabilities= client_capabilities;
118+ backup->savepoints= transaction.savepoints;
119+@@ -3656,6 +3689,7 @@
120 first_successful_insert_id_in_prev_stmt;
121 backup->first_successful_insert_id_in_cur_stmt=
122 first_successful_insert_id_in_cur_stmt;
123-+ backup->innodb_io_reads= innodb_io_reads;
124-+ backup->innodb_io_read= innodb_io_read;
125-+ backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
126-+ backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
127-+ backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
128-+ backup->innodb_page_access= innodb_page_access;
129++ reset_sub_statement_state_slow_extended(backup);
130
131 if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
132 !is_current_stmt_binlog_format_row())
133-@@ -3676,6 +3715,14 @@
134+@@ -3671,13 +3705,74 @@
135+ /* Disable result sets */
136+ client_capabilities &= ~CLIENT_MULTI_RESULTS;
137+ in_sub_stmt|= new_state;
138+- examined_row_count= 0;
139+- sent_row_count= 0;
140 cuted_fields= 0;
141 transaction.savepoints= 0;
142 first_successful_insert_id_in_cur_stmt= 0;
143-+ last_errno= 0;
144-+ innodb_trx_id= 0;
145-+ innodb_io_reads= 0;
146-+ innodb_io_read= 0;
147-+ innodb_io_reads_wait_timer= 0;
148-+ innodb_lock_que_wait_timer= 0;
149+ }
150+
151++void THD::clear_slow_extended()
152++{
153++ DBUG_ENTER("THD::clear_slow_extended");
154++ sent_row_count= 0;
155++ examined_row_count= 0;
156++ bytes_sent_old= status_var.bytes_sent;
157++ tmp_tables_used= 0;
158++ tmp_tables_disk_used= 0;
159++ tmp_tables_size= 0;
160++ innodb_was_used= FALSE;
161++ innodb_trx_id= 0;
162++ innodb_io_reads= 0;
163++ innodb_io_read= 0;
164++ innodb_io_reads_wait_timer= 0;
165++ innodb_lock_que_wait_timer= 0;
166 + innodb_innodb_que_wait_timer= 0;
167-+ innodb_page_access= 0;
168- }
169-
170-
171-@@ -3738,6 +3785,12 @@
172++ innodb_page_access= 0;
173++ query_plan_flags= QPLAN_NONE;
174++ query_plan_fsort_passes= 0;
175++ last_errno= 0;
176++ DBUG_VOID_RETURN;
177++}
178++
179++void THD::reset_sub_statement_state_slow_extended(Sub_statement_state *backup)
180++{
181++ DBUG_ENTER("THD::reset_sub_statement_state_slow_extended");
182++ backup->sent_row_count= sent_row_count;
183++ backup->examined_row_count= examined_row_count;
184++ backup->tmp_tables_used= tmp_tables_used;
185++ backup->tmp_tables_disk_used= tmp_tables_disk_used;
186++ backup->tmp_tables_size= tmp_tables_size;
187++ backup->innodb_was_used= innodb_was_used;
188++ backup->innodb_io_reads= innodb_io_reads;
189++ backup->innodb_io_read= innodb_io_read;
190++ backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
191++ backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
192++ backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
193++ backup->innodb_page_access= innodb_page_access;
194++ backup->query_plan_flags= query_plan_flags;
195++ backup->query_plan_fsort_passes= query_plan_fsort_passes;
196++ clear_slow_extended();
197++ DBUG_VOID_RETURN;
198++}
199++
200++void THD::restore_sub_statement_state_slow_extended(Sub_statement_state *backup)
201++{
202++ DBUG_ENTER("THD::restore_sub_statement_state_slow_extended");
203++ sent_row_count= backup->sent_row_count;
204++ examined_row_count+= backup->examined_row_count;
205++ tmp_tables_used+= backup->tmp_tables_used;
206++ tmp_tables_disk_used+= backup->tmp_tables_disk_used;
207++ tmp_tables_size+= backup->tmp_tables_size;
208++ innodb_was_used= (innodb_was_used || backup->innodb_was_used);
209++ innodb_io_reads+= backup->innodb_io_reads;
210++ innodb_io_read+= backup->innodb_io_read;
211++ innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
212++ innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
213++ innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
214++ innodb_page_access+= backup->innodb_page_access;
215++ query_plan_flags|= backup->query_plan_flags;
216++ query_plan_fsort_passes+= backup->query_plan_fsort_passes;
217++ DBUG_VOID_RETURN;
218++}
219+
220+ void THD::restore_sub_statement_state(Sub_statement_state *backup)
221+ {
222+@@ -3718,7 +3813,6 @@
223+ first_successful_insert_id_in_cur_stmt=
224+ backup->first_successful_insert_id_in_cur_stmt;
225+ limit_found_rows= backup->limit_found_rows;
226+- sent_row_count= backup->sent_row_count;
227+ client_capabilities= backup->client_capabilities;
228+ /*
229+ If we've left sub-statement mode, reset the fatal error flag.
230+@@ -3736,8 +3830,8 @@
231+ The following is added to the old values as we are interested in the
232+ total complexity of the query
233 */
234- examined_row_count+= backup->examined_row_count;
235+- examined_row_count+= backup->examined_row_count;
236 cuted_fields+= backup->cuted_fields;
237-+ innodb_io_reads+= backup->innodb_io_reads;
238-+ innodb_io_read+= backup->innodb_io_read;
239-+ innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
240-+ innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
241-+ innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
242-+ innodb_page_access+= backup->innodb_page_access;
243++ restore_sub_statement_state_slow_extended(backup);
244 DBUG_VOID_RETURN;
245 }
246
247@@ -661,11 +730,17 @@
248 double long_query_time_double;
249
250 } SV;
251-@@ -1140,6 +1182,14 @@
252+@@ -1140,6 +1182,24 @@
253 uint in_sub_stmt;
254 bool enable_slow_log;
255 bool last_insert_id_used;
256 +
257++ /*** Following variables used in slow_extended.patch ***/
258++ ulong tmp_tables_used;
259++ ulong tmp_tables_disk_used;
260++ ulonglong tmp_tables_size;
261++
262++ bool innodb_was_used;
263 + ulong innodb_io_reads;
264 + ulonglong innodb_io_read;
265 + ulong innodb_io_reads_wait_timer;
266@@ -673,20 +748,50 @@
267 + ulong innodb_innodb_que_wait_timer;
268 + ulong innodb_page_access;
269 +
270++ ulong query_plan_flags;
271++ ulong query_plan_fsort_passes;
272++ /*** Belowing variables and methods used in slow_extended.patch ***/
273++
274 SAVEPOINT *savepoints;
275 enum enum_check_fields count_cuted_fields;
276 };
277-@@ -1588,6 +1638,26 @@
278+@@ -1588,6 +1648,72 @@
279 thr_lock_type update_lock_default;
280 Delayed_insert *di;
281
282++ /*** Following variables used in slow_extended.patch ***/
283++ /*
284++ Variable write_to_slow _log:
285++ 1) inited in
286++ * sql_connect.cc (log_slow_rate_limit support)
287++ * slave.cc (log_slow_slave_statements support)
288++ 2) variable never changed while thread works
289++ * ATTENTION: this would be changed according to:
290++ Launchpad bug #712396: "log_slow_slave_statements not work
291++ on replication threads without RESTART"
292++ 3) variable should be used for:
293++ LP bug #688646: "Make query sampling possible by query"
294++ */
295 + bool write_to_slow_log;
296-+
297++ /*
298++ Variable bytes_send_old save value of thd->status_var.bytes_sent
299++ before query execution.
300++ */
301 + ulonglong bytes_sent_old;
302++ /*
303++ Variables tmp_tables_*** collect statistics about usage of temporary tables
304++ */
305 + ulong tmp_tables_used;
306 + ulong tmp_tables_disk_used;
307 + ulonglong tmp_tables_size;
308++ /*
309++ Variable innodb_was used show used or not InnoDB engine in current query.
310++ */
311 + bool innodb_was_used;
312++ /*
313++ Following Variables innodb_*** (is |should be) different from
314++ default values only if (innodb_was_used==TRUE)
315++ */
316 + ulonglong innodb_trx_id;
317 + ulong innodb_io_reads;
318 + ulonglong innodb_io_read;
319@@ -695,10 +800,30 @@
320 + ulong innodb_innodb_que_wait_timer;
321 + ulong innodb_page_access;
322 +
323++ /*
324++ Variable query_plan_flags collect information about query plan entites
325++ used on query execution.
326++ */
327 + ulong query_plan_flags;
328++ /*
329++ Variable query_plan_fsort_passes collect information about file sort passes
330++ acquired during query execution.
331++ */
332 + ulong query_plan_fsort_passes;
333-+
334++ /*
335++ Query can generates several errors/warnings during execution
336++ (see THD::handle_condition comment in sql_class.h)
337++ Variable last_errno contain last error/warning acquired during
338++ query execution.
339++ */
340 + uint last_errno;
341++ /*** Belowing variables and methods used in slow_extended.patch ***/
342++
343++ /*** Following methods used in slow_extended.patch ***/
344++ void clear_slow_extended();
345++ void reset_sub_statement_state_slow_extended(Sub_statement_state *backup);
346++ void restore_sub_statement_state_slow_extended(Sub_statement_state *backup);
347++ /*** Belowing methods used in slow_extended.patch ***/
348 +
349 /* <> 0 if we are inside of trigger or stored function. */
350 uint in_sub_stmt;
351@@ -731,7 +856,15 @@
352
353 const char *any_db="*any*"; // Special symbol for check_access
354
355-@@ -1430,6 +1431,60 @@
356+@@ -888,6 +889,7 @@
357+ the slow log only if opt_log_slow_admin_statements is set.
358+ */
359+ thd->enable_slow_log= TRUE;
360++ thd->clear_slow_extended();
361+ thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
362+ thd->set_time();
363+ if (!thd->is_valid_time())
364+@@ -1430,6 +1432,60 @@
365 DBUG_RETURN(error);
366 }
367
368@@ -792,7 +925,7 @@
369
370 void log_slow_statement(THD *thd)
371 {
372-@@ -1443,13 +1498,48 @@
373+@@ -1443,13 +1499,48 @@
374 if (unlikely(thd->in_sub_stmt))
375 DBUG_VOID_RETURN; // Don't set time for sub stmt
376
377@@ -842,38 +975,16 @@
378 thd_proc_info(thd, "logging slow query");
379
380 if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
381-@@ -1879,6 +1969,9 @@
382- context.resolve_in_table_list_only(select_lex->
383- table_list.first);
384-
385-+ /* Reset the counter at all cases for the extended slow query log */
386-+ thd->sent_row_count= 0;
387-+
388- /*
389- Reset warning count for each query that uses tables
390- A better approach would be to reset this for any commands
391-@@ -5297,6 +5390,21 @@
392+@@ -5295,7 +5386,8 @@
393+ thd->stmt_da->reset_diagnostics_area();
394+ thd->warning_info->reset_for_next_command();
395 thd->rand_used= 0;
396- thd->sent_row_count= thd->examined_row_count= 0;
397+- thd->sent_row_count= thd->examined_row_count= 0;
398++
399++ thd->clear_slow_extended();
400
401-+ thd->bytes_sent_old= thd->status_var.bytes_sent;
402-+ thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
403-+ thd->tmp_tables_size= 0;
404-+ thd->innodb_was_used= FALSE;
405-+ thd->innodb_trx_id= 0;
406-+ thd->innodb_io_reads= 0;
407-+ thd->innodb_io_read= 0;
408-+ thd->innodb_io_reads_wait_timer= 0;
409-+ thd->innodb_lock_que_wait_timer= 0;
410-+ thd->innodb_innodb_que_wait_timer= 0;
411-+ thd->innodb_page_access= 0;
412-+ thd->query_plan_flags= QPLAN_NONE;
413-+ thd->query_plan_fsort_passes= 0;
414-+ thd->last_errno= 0;
415-+
416 thd->reset_current_stmt_binlog_format_row();
417 thd->binlog_unsafe_warning_flags= 0;
418-
419 --- a/sql/sql_select.cc
420 +++ b/sql/sql_select.cc
421 @@ -6902,7 +6902,10 @@
422@@ -2425,6 +2536,7 @@
423 +--let grep_pattern = Last_errno: 1050
424 +--source include/log_grep.inc
425 +DROP TABLE t;
426+<<<<<<< TREE
427 --- /dev/null
428 +++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_basic.test
429 @@ -0,0 +1 @@
430@@ -2574,3 +2686,322 @@
431 @@ -0,0 +1,2 @@
432 +SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
433 +SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
434+=======
435+--- /dev/null
436++++ b/mysql-test/t/percona_slow_extended_error_on_quit.test
437+@@ -0,0 +1,87 @@
438++################################################################################
439++# Current test check following attributes: #
440++# 1) "Last_errno" #
441++# 2) "Rows_{sent,examined|affected|read} #
442++# 3) Bytes_sent #
443++# 4) Tmp_{tables|dist_tables|table_size} #
444++# 5) InnoDB statistic counters #
445++# in Slow Query Log #
446++# for administrative command "Quit" #
447++# #
448++# See Launchpad Bug #716210 #
449++################################################################################
450++
451++--source include/have_innodb.inc
452++
453++################################################################################
454++--let log_file=percona.slow_extended.error_on_quit
455++--let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST;
456++################################################################################
457++
458++--disable_warnings
459++DROP TABLE IF EXISTS t;
460++--enable_warnings
461++CREATE TABLE t(a INT) engine=InnoDB;
462++INSERT INTO t VALUES(0),(1),(2),(3),(4);
463++
464++################################################################################
465++--source include/log_start.inc
466++
467++--connect(additional,localhost,root,,)
468++--connection additional
469++
470++ SET log_slow_verbosity=innodb;
471++ SET long_query_time= 0;
472++
473++--disable_result_log
474++--error ER_TABLE_EXISTS_ERROR
475++ CREATE TABLE t(a INT) engine=InnoDB;
476++--enable_result_log
477++
478++--connection default
479++--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
480++--disconnect additional
481++--source include/wait_condition.inc
482++--source include/log_stop.inc
483++--source include/percona_slow_extended_error_on_quit.inc
484++################################################################################
485++--source include/log_start.inc
486++
487++--connect(additional,localhost,root,,)
488++--connection additional
489++
490++ SET log_slow_verbosity=innodb;
491++ SET long_query_time= 0;
492++
493++--disable_result_log
494++ INSERT INTO t SELECT * FROM t ORDER BY RAND();
495++--enable_result_log
496++
497++--connection default
498++--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
499++--disconnect additional
500++--source include/wait_condition.inc
501++--source include/log_stop.inc
502++--source include/percona_slow_extended_error_on_quit.inc
503++################################################################################
504++--source include/log_start.inc
505++
506++--connect(additional,localhost,root,,)
507++--connection additional
508++
509++ SET log_slow_verbosity=innodb;
510++ SET long_query_time= 0;
511++
512++--disable_result_log
513++ SELECT * FROM t;
514++--enable_result_log
515++
516++--connection default
517++--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
518++--disconnect additional
519++--source include/wait_condition.inc
520++--source include/log_stop.inc
521++--source include/percona_slow_extended_error_on_quit.inc
522++################################################################################
523++
524++DROP TABLE t;
525+--- /dev/null
526++++ b/mysql-test/r/percona_slow_extended_error_on_quit.result
527+@@ -0,0 +1,171 @@
528++DROP TABLE IF EXISTS t;
529++CREATE TABLE t(a INT) engine=InnoDB;
530++INSERT INTO t VALUES(0),(1),(2),(3),(4);
531++[log_start.inc] percona.slow_extended.error_on_quit
532++SET log_slow_verbosity=innodb;
533++SET long_query_time= 0;
534++CREATE TABLE t(a INT) engine=InnoDB;
535++# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
536++[log_stop.inc] percona.slow_extended.error_on_quit
537++################################################################################
538++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
539++[log_grep.inc] lines: 1
540++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
541++[log_grep.inc] lines: 0
542++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
543++[log_grep.inc] lines: 0
544++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
545++[log_grep.inc] lines: 1
546++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
547++[log_grep.inc] lines: 1
548++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
549++[log_grep.inc] lines: 2
550++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
551++[log_grep.inc] lines: 0
552++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
553++[log_grep.inc] lines: 3
554++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
555++[log_grep.inc] lines: 0
556++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
557++[log_grep.inc] lines: 3
558++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
559++[log_grep.inc] lines: 0
560++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
561++[log_grep.inc] lines: 3
562++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
563++[log_grep.inc] lines: 0
564++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
565++[log_grep.inc] lines: 3
566++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
567++[log_grep.inc] lines: 2
568++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
569++[log_grep.inc] lines: 1
570++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
571++[log_grep.inc] lines: 0
572++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
573++[log_grep.inc] lines: 3
574++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
575++[log_grep.inc] lines: 0
576++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
577++[log_grep.inc] lines: 3
578++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
579++[log_grep.inc] lines: 0
580++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
581++[log_grep.inc] lines: 3
582++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
583++[log_grep.inc] lines: 2
584++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id:
585++[log_grep.inc] lines: 1
586++################################################################################
587++[log_start.inc] percona.slow_extended.error_on_quit
588++SET log_slow_verbosity=innodb;
589++SET long_query_time= 0;
590++INSERT INTO t SELECT * FROM t ORDER BY RAND();
591++# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
592++[log_stop.inc] percona.slow_extended.error_on_quit
593++################################################################################
594++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
595++[log_grep.inc] lines: 0
596++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
597++[log_grep.inc] lines: 1
598++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
599++[log_grep.inc] lines: 1
600++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
601++[log_grep.inc] lines: 1
602++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
603++[log_grep.inc] lines: 0
604++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
605++[log_grep.inc] lines: 3
606++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
607++[log_grep.inc] lines: 0
608++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
609++[log_grep.inc] lines: 3
610++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
611++[log_grep.inc] lines: 1
612++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
613++[log_grep.inc] lines: 2
614++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
615++[log_grep.inc] lines: 2
616++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
617++[log_grep.inc] lines: 1
618++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
619++[log_grep.inc] lines: 0
620++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
621++[log_grep.inc] lines: 3
622++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
623++[log_grep.inc] lines: 2
624++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
625++[log_grep.inc] lines: 1
626++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
627++[log_grep.inc] lines: 1
628++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
629++[log_grep.inc] lines: 2
630++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
631++[log_grep.inc] lines: 0
632++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
633++[log_grep.inc] lines: 3
634++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
635++[log_grep.inc] lines: 1
636++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
637++[log_grep.inc] lines: 2
638++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
639++[log_grep.inc] lines: 2
640++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id:
641++[log_grep.inc] lines: 1
642++################################################################################
643++[log_start.inc] percona.slow_extended.error_on_quit
644++SET log_slow_verbosity=innodb;
645++SET long_query_time= 0;
646++SELECT * FROM t;
647++# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
648++[log_stop.inc] percona.slow_extended.error_on_quit
649++################################################################################
650++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
651++[log_grep.inc] lines: 0
652++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
653++[log_grep.inc] lines: 0
654++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
655++[log_grep.inc] lines: 1
656++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
657++[log_grep.inc] lines: 1
658++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
659++[log_grep.inc] lines: 0
660++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
661++[log_grep.inc] lines: 3
662++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
663++[log_grep.inc] lines: 1
664++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
665++[log_grep.inc] lines: 2
666++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
667++[log_grep.inc] lines: 1
668++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
669++[log_grep.inc] lines: 2
670++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
671++[log_grep.inc] lines: 0
672++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
673++[log_grep.inc] lines: 3
674++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
675++[log_grep.inc] lines: 1
676++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
677++[log_grep.inc] lines: 2
678++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
679++[log_grep.inc] lines: 2
680++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
681++[log_grep.inc] lines: 1
682++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
683++[log_grep.inc] lines: 0
684++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
685++[log_grep.inc] lines: 3
686++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
687++[log_grep.inc] lines: 0
688++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
689++[log_grep.inc] lines: 3
690++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
691++[log_grep.inc] lines: 0
692++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
693++[log_grep.inc] lines: 3
694++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
695++[log_grep.inc] lines: 2
696++[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id:
697++[log_grep.inc] lines: 1
698++################################################################################
699+--- /dev/null
700++++ b/mysql-test/include/percona_slow_extended_error_on_quit.inc
701+@@ -0,0 +1,50 @@
702++--echo ################################################################################
703++--let grep_pattern=CREATE
704++--source include/log_grep.inc
705++--let grep_pattern=INSERT
706++--source include/log_grep.inc
707++--let grep_pattern=SELECT
708++--source include/log_grep.inc
709++--let grep_pattern=Quit
710++--source include/log_grep.inc
711++--let grep_pattern=Last_errno: [^0]+
712++--source include/log_grep.inc
713++--let grep_pattern=Last_errno: 0
714++--source include/log_grep.inc
715++--let grep_pattern=Rows_sent: [^0]+
716++--source include/log_grep.inc
717++--let grep_pattern=Rows_sent: 0
718++--source include/log_grep.inc
719++--let grep_pattern=Rows_examined: [^0]+
720++--source include/log_grep.inc
721++--let grep_pattern=Rows_examined: 0
722++--source include/log_grep.inc
723++--let grep_pattern=Rows_affected: [^0]+
724++--source include/log_grep.inc
725++--let grep_pattern=Rows_affected: 0
726++--source include/log_grep.inc
727++--let grep_pattern=Rows_read: [^0]+
728++--source include/log_grep.inc
729++--let grep_pattern=Rows_read: 0
730++--source include/log_grep.inc
731++--let grep_pattern=Bytes_sent: [^0]+
732++--source include/log_grep.inc
733++--let grep_pattern=Bytes_sent: 0
734++--source include/log_grep.inc
735++--let grep_pattern=Tmp_tables: [^0]+
736++--source include/log_grep.inc
737++--let grep_pattern=Tmp_tables: 0
738++--source include/log_grep.inc
739++--let grep_pattern=Tmp_disk_tables: [^0]+
740++--source include/log_grep.inc
741++--let grep_pattern=Tmp_disk_tables: 0
742++--source include/log_grep.inc
743++--let grep_pattern=Tmp_table_sizes: [^0]+
744++--source include/log_grep.inc
745++--let grep_pattern=Tmp_table_sizes: 0
746++--source include/log_grep.inc
747++--let grep_pattern=# No InnoDB statistics available for this query
748++--source include/log_grep.inc
749++--let grep_pattern=# InnoDB_trx_id:
750++--source include/log_grep.inc
751++--echo ################################################################################
752+>>>>>>> MERGE-SOURCE

Subscribers

People subscribed via source and target branches