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

Proposed by Oleg Tsarev
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 (community) Needs Fixing
Alexey Kopytov 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.
Revision history for this message
Oleg Tsarev (tsarev) wrote : Posted in a previous version of this proposal
Revision history for this message
Oleg Tsarev (tsarev) wrote : Posted in a previous version of this proposal
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote : Posted in a previous version of this proposal

LGTM provided that Jenkins result are clean

review: Approve
Revision history for this message
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
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) 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?
- 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
Revision history for this message
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)

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

> 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

extend tests

Unmerged revisions

152. By Oleg Tsarev

extend tests

151. By Oleg Tsarev

  * "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
=== modified file 'patches/slow_extended.patch'
--- patches/slow_extended.patch 2011-09-28 14:25:37 +0000
+++ patches/slow_extended.patch 2011-10-06 23:44:24 +0000
@@ -227,29 +227,16 @@
227 }227 }
228 else228 else
229 {229 {
230@@ -1239,8 +1255,20 @@230@@ -1240,7 +1256,7 @@
231 query_length= command_name[thd->command].length;
232 }231 }
233 232
234+ if (!query_length)
235+ {
236+ thd->sent_row_count= thd->examined_row_count= 0;
237+ thd->sent_row_count= 0;
238+ thd->bytes_sent_old= thd->status_var.bytes_sent;
239+ thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
240+ thd->tmp_tables_size= 0;
241+ thd->innodb_was_used= FALSE;
242+ thd->query_plan_flags= QPLAN_NONE;
243+ thd->query_plan_fsort_passes= 0;
244+ }
245+
246 for (current_handler= slow_log_handler_list; *current_handler ;)233 for (current_handler= slow_log_handler_list; *current_handler ;)
247- error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,234- error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
248+ error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,235+ error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
249 user_host_buff, user_host_len,236 user_host_buff, user_host_len,
250 query_utime, lock_utime, is_command,237 query_utime, lock_utime, is_command,
251 query, query_length) || error;238 query, query_length) || error;
252@@ -2656,12 +2684,13 @@239@@ -2656,12 +2672,13 @@
253 TRUE - error occured240 TRUE - error occured
254 */241 */
255 242
@@ -264,7 +251,7 @@
264 bool error= 0;251 bool error= 0;
265 DBUG_ENTER("MYSQL_QUERY_LOG::write");252 DBUG_ENTER("MYSQL_QUERY_LOG::write");
266 253
267@@ -2683,17 +2712,28 @@254@@ -2683,17 +2700,28 @@
268 255
269 if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))256 if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
270 {257 {
@@ -300,9 +287,11 @@
300 287
301 /* Note that my_b_write() assumes it knows the length for this */288 /* Note that my_b_write() assumes it knows the length for this */
302 if (my_b_write(&log_file, (uchar*) buff, buff_len))289 if (my_b_write(&log_file, (uchar*) buff, buff_len))
303@@ -2711,12 +2751,69 @@290@@ -2710,13 +2738,71 @@
291 /* For slow query log */
304 sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);292 sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
305 sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0);293 sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0);
294+ DBUG_PRINT("info", ("Last_errno: %u", thd->last_errno));
306 if (my_b_printf(&log_file,295 if (my_b_printf(&log_file,
307- "# Query_time: %s Lock_time: %s"296- "# Query_time: %s Lock_time: %s"
308- " Rows_sent: %lu Rows_examined: %lu\n",297- " Rows_sent: %lu Rows_examined: %lu\n",
@@ -521,22 +510,22 @@
521 510
522+extern "C"511+extern "C"
523+void increment_thd_innodb_stats(THD* thd,512+void increment_thd_innodb_stats(THD* thd,
524+ unsigned long long trx_id,513+ unsigned long long trx_id,
525+ long io_reads,514+ long io_reads,
526+ long long io_read,515+ long long io_read,
527+ long io_reads_wait_timer,516+ long io_reads_wait_timer,
528+ long lock_que_wait_timer,517+ long lock_que_wait_timer,
529+ long que_wait_timer,518+ long que_wait_timer,
530+ long page_access)519+ long page_access)
531+{520+{
532+ thd->innodb_was_used = TRUE;521+ thd->innodb_was_used= TRUE;
533+ thd->innodb_trx_id = trx_id;522+ thd->innodb_trx_id= trx_id;
534+ thd->innodb_io_reads += io_reads;523+ thd->innodb_io_reads+= io_reads;
535+ thd->innodb_io_read += io_read;524+ thd->innodb_io_read+= io_read;
536+ thd->innodb_io_reads_wait_timer += io_reads_wait_timer;525+ thd->innodb_io_reads_wait_timer+= io_reads_wait_timer;
537+ thd->innodb_lock_que_wait_timer += lock_que_wait_timer;526+ thd->innodb_lock_que_wait_timer+= lock_que_wait_timer;
538+ thd->innodb_innodb_que_wait_timer += que_wait_timer;527+ thd->innodb_innodb_que_wait_timer+= que_wait_timer;
539+ thd->innodb_page_access += page_access;528+ thd->innodb_page_access+= page_access;
540+}529+}
541+530+
542+extern "C"531+extern "C"
@@ -562,44 +551,124 @@
562 if (!m_internal_handler)551 if (!m_internal_handler)
563 {552 {
564 *cond_hdl= NULL;553 *cond_hdl= NULL;
565@@ -3656,6 +3689,12 @@554@@ -1201,6 +1234,8 @@
555 /* Initialize the Debug Sync Facility. See debug_sync.cc. */
556 debug_sync_init_thread(this);
557 #endif /* defined(ENABLED_DEBUG_SYNC) */
558+
559+ clear_slow_extended();
560 }
561
562
563@@ -3647,8 +3682,6 @@
564 backup->in_sub_stmt= in_sub_stmt;
565 backup->enable_slow_log= enable_slow_log;
566 backup->limit_found_rows= limit_found_rows;
567- backup->examined_row_count= examined_row_count;
568- backup->sent_row_count= sent_row_count;
569 backup->cuted_fields= cuted_fields;
570 backup->client_capabilities= client_capabilities;
571 backup->savepoints= transaction.savepoints;
572@@ -3656,6 +3689,7 @@
566 first_successful_insert_id_in_prev_stmt;573 first_successful_insert_id_in_prev_stmt;
567 backup->first_successful_insert_id_in_cur_stmt= 574 backup->first_successful_insert_id_in_cur_stmt=
568 first_successful_insert_id_in_cur_stmt;575 first_successful_insert_id_in_cur_stmt;
569+ backup->innodb_io_reads= innodb_io_reads;576+ reset_sub_statement_state_slow_extended(backup);
570+ backup->innodb_io_read= innodb_io_read;
571+ backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
572+ backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
573+ backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
574+ backup->innodb_page_access= innodb_page_access;
575 577
576 if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&578 if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
577 !is_current_stmt_binlog_format_row())579 !is_current_stmt_binlog_format_row())
578@@ -3676,6 +3715,14 @@580@@ -3671,13 +3705,74 @@
581 /* Disable result sets */
582 client_capabilities &= ~CLIENT_MULTI_RESULTS;
583 in_sub_stmt|= new_state;
584- examined_row_count= 0;
585- sent_row_count= 0;
579 cuted_fields= 0;586 cuted_fields= 0;
580 transaction.savepoints= 0;587 transaction.savepoints= 0;
581 first_successful_insert_id_in_cur_stmt= 0;588 first_successful_insert_id_in_cur_stmt= 0;
582+ last_errno= 0;589 }
583+ innodb_trx_id= 0;590
584+ innodb_io_reads= 0;591+void THD::clear_slow_extended()
585+ innodb_io_read= 0;592+{
586+ innodb_io_reads_wait_timer= 0;593+ DBUG_ENTER("THD::clear_slow_extended");
587+ innodb_lock_que_wait_timer= 0;594+ sent_row_count= 0;
595+ examined_row_count= 0;
596+ bytes_sent_old= status_var.bytes_sent;
597+ tmp_tables_used= 0;
598+ tmp_tables_disk_used= 0;
599+ tmp_tables_size= 0;
600+ innodb_was_used= FALSE;
601+ innodb_trx_id= 0;
602+ innodb_io_reads= 0;
603+ innodb_io_read= 0;
604+ innodb_io_reads_wait_timer= 0;
605+ innodb_lock_que_wait_timer= 0;
588+ innodb_innodb_que_wait_timer= 0;606+ innodb_innodb_que_wait_timer= 0;
589+ innodb_page_access= 0;607+ innodb_page_access= 0;
590 }608+ query_plan_flags= QPLAN_NONE;
591 609+ query_plan_fsort_passes= 0;
592 610+ last_errno= 0;
593@@ -3738,6 +3785,12 @@611+ DBUG_VOID_RETURN;
612+}
613+
614+void THD::reset_sub_statement_state_slow_extended(Sub_statement_state *backup)
615+{
616+ DBUG_ENTER("THD::reset_sub_statement_state_slow_extended");
617+ backup->sent_row_count= sent_row_count;
618+ backup->examined_row_count= examined_row_count;
619+ backup->tmp_tables_used= tmp_tables_used;
620+ backup->tmp_tables_disk_used= tmp_tables_disk_used;
621+ backup->tmp_tables_size= tmp_tables_size;
622+ backup->innodb_was_used= innodb_was_used;
623+ backup->innodb_io_reads= innodb_io_reads;
624+ backup->innodb_io_read= innodb_io_read;
625+ backup->innodb_io_reads_wait_timer= innodb_io_reads_wait_timer;
626+ backup->innodb_lock_que_wait_timer= innodb_lock_que_wait_timer;
627+ backup->innodb_innodb_que_wait_timer= innodb_innodb_que_wait_timer;
628+ backup->innodb_page_access= innodb_page_access;
629+ backup->query_plan_flags= query_plan_flags;
630+ backup->query_plan_fsort_passes= query_plan_fsort_passes;
631+ clear_slow_extended();
632+ DBUG_VOID_RETURN;
633+}
634+
635+void THD::restore_sub_statement_state_slow_extended(Sub_statement_state *backup)
636+{
637+ DBUG_ENTER("THD::restore_sub_statement_state_slow_extended");
638+ sent_row_count= backup->sent_row_count;
639+ examined_row_count+= backup->examined_row_count;
640+ tmp_tables_used+= backup->tmp_tables_used;
641+ tmp_tables_disk_used+= backup->tmp_tables_disk_used;
642+ tmp_tables_size+= backup->tmp_tables_size;
643+ innodb_was_used= (innodb_was_used || backup->innodb_was_used);
644+ innodb_io_reads+= backup->innodb_io_reads;
645+ innodb_io_read+= backup->innodb_io_read;
646+ innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
647+ innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
648+ innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
649+ innodb_page_access+= backup->innodb_page_access;
650+ query_plan_flags|= backup->query_plan_flags;
651+ query_plan_fsort_passes+= backup->query_plan_fsort_passes;
652+ DBUG_VOID_RETURN;
653+}
654
655 void THD::restore_sub_statement_state(Sub_statement_state *backup)
656 {
657@@ -3718,7 +3813,6 @@
658 first_successful_insert_id_in_cur_stmt=
659 backup->first_successful_insert_id_in_cur_stmt;
660 limit_found_rows= backup->limit_found_rows;
661- sent_row_count= backup->sent_row_count;
662 client_capabilities= backup->client_capabilities;
663 /*
664 If we've left sub-statement mode, reset the fatal error flag.
665@@ -3736,8 +3830,8 @@
666 The following is added to the old values as we are interested in the
667 total complexity of the query
594 */668 */
595 examined_row_count+= backup->examined_row_count;669- examined_row_count+= backup->examined_row_count;
596 cuted_fields+= backup->cuted_fields;670 cuted_fields+= backup->cuted_fields;
597+ innodb_io_reads+= backup->innodb_io_reads;671+ restore_sub_statement_state_slow_extended(backup);
598+ innodb_io_read+= backup->innodb_io_read;
599+ innodb_io_reads_wait_timer+= backup->innodb_io_reads_wait_timer;
600+ innodb_lock_que_wait_timer+= backup->innodb_lock_que_wait_timer;
601+ innodb_innodb_que_wait_timer+= backup->innodb_innodb_que_wait_timer;
602+ innodb_page_access+= backup->innodb_page_access;
603 DBUG_VOID_RETURN;672 DBUG_VOID_RETURN;
604 }673 }
605 674
@@ -661,11 +730,17 @@
661 double long_query_time_double;730 double long_query_time_double;
662 731
663 } SV;732 } SV;
664@@ -1140,6 +1182,14 @@733@@ -1140,6 +1182,24 @@
665 uint in_sub_stmt;734 uint in_sub_stmt;
666 bool enable_slow_log;735 bool enable_slow_log;
667 bool last_insert_id_used;736 bool last_insert_id_used;
668+737+
738+ /*** Following variables used in slow_extended.patch ***/
739+ ulong tmp_tables_used;
740+ ulong tmp_tables_disk_used;
741+ ulonglong tmp_tables_size;
742+
743+ bool innodb_was_used;
669+ ulong innodb_io_reads;744+ ulong innodb_io_reads;
670+ ulonglong innodb_io_read;745+ ulonglong innodb_io_read;
671+ ulong innodb_io_reads_wait_timer;746+ ulong innodb_io_reads_wait_timer;
@@ -673,20 +748,50 @@
673+ ulong innodb_innodb_que_wait_timer;748+ ulong innodb_innodb_que_wait_timer;
674+ ulong innodb_page_access;749+ ulong innodb_page_access;
675+750+
751+ ulong query_plan_flags;
752+ ulong query_plan_fsort_passes;
753+ /*** Belowing variables and methods used in slow_extended.patch ***/
754+
676 SAVEPOINT *savepoints;755 SAVEPOINT *savepoints;
677 enum enum_check_fields count_cuted_fields;756 enum enum_check_fields count_cuted_fields;
678 };757 };
679@@ -1588,6 +1638,26 @@758@@ -1588,6 +1648,72 @@
680 thr_lock_type update_lock_default;759 thr_lock_type update_lock_default;
681 Delayed_insert *di;760 Delayed_insert *di;
682 761
762+ /*** Following variables used in slow_extended.patch ***/
763+ /*
764+ Variable write_to_slow _log:
765+ 1) inited in
766+ * sql_connect.cc (log_slow_rate_limit support)
767+ * slave.cc (log_slow_slave_statements support)
768+ 2) variable never changed while thread works
769+ * ATTENTION: this would be changed according to:
770+ Launchpad bug #712396: "log_slow_slave_statements not work
771+ on replication threads without RESTART"
772+ 3) variable should be used for:
773+ LP bug #688646: "Make query sampling possible by query"
774+ */
683+ bool write_to_slow_log;775+ bool write_to_slow_log;
684+776+ /*
777+ Variable bytes_send_old save value of thd->status_var.bytes_sent
778+ before query execution.
779+ */
685+ ulonglong bytes_sent_old;780+ ulonglong bytes_sent_old;
781+ /*
782+ Variables tmp_tables_*** collect statistics about usage of temporary tables
783+ */
686+ ulong tmp_tables_used;784+ ulong tmp_tables_used;
687+ ulong tmp_tables_disk_used;785+ ulong tmp_tables_disk_used;
688+ ulonglong tmp_tables_size;786+ ulonglong tmp_tables_size;
787+ /*
788+ Variable innodb_was used show used or not InnoDB engine in current query.
789+ */
689+ bool innodb_was_used;790+ bool innodb_was_used;
791+ /*
792+ Following Variables innodb_*** (is |should be) different from
793+ default values only if (innodb_was_used==TRUE)
794+ */
690+ ulonglong innodb_trx_id;795+ ulonglong innodb_trx_id;
691+ ulong innodb_io_reads;796+ ulong innodb_io_reads;
692+ ulonglong innodb_io_read;797+ ulonglong innodb_io_read;
@@ -695,10 +800,30 @@
695+ ulong innodb_innodb_que_wait_timer;800+ ulong innodb_innodb_que_wait_timer;
696+ ulong innodb_page_access;801+ ulong innodb_page_access;
697+802+
803+ /*
804+ Variable query_plan_flags collect information about query plan entites
805+ used on query execution.
806+ */
698+ ulong query_plan_flags;807+ ulong query_plan_flags;
808+ /*
809+ Variable query_plan_fsort_passes collect information about file sort passes
810+ acquired during query execution.
811+ */
699+ ulong query_plan_fsort_passes;812+ ulong query_plan_fsort_passes;
700+813+ /*
814+ Query can generates several errors/warnings during execution
815+ (see THD::handle_condition comment in sql_class.h)
816+ Variable last_errno contain last error/warning acquired during
817+ query execution.
818+ */
701+ uint last_errno;819+ uint last_errno;
820+ /*** Belowing variables and methods used in slow_extended.patch ***/
821+
822+ /*** Following methods used in slow_extended.patch ***/
823+ void clear_slow_extended();
824+ void reset_sub_statement_state_slow_extended(Sub_statement_state *backup);
825+ void restore_sub_statement_state_slow_extended(Sub_statement_state *backup);
826+ /*** Belowing methods used in slow_extended.patch ***/
702+827+
703 /* <> 0 if we are inside of trigger or stored function. */828 /* <> 0 if we are inside of trigger or stored function. */
704 uint in_sub_stmt;829 uint in_sub_stmt;
@@ -731,7 +856,15 @@
731 856
732 const char *any_db="*any*"; // Special symbol for check_access857 const char *any_db="*any*"; // Special symbol for check_access
733 858
734@@ -1430,6 +1431,60 @@859@@ -888,6 +889,7 @@
860 the slow log only if opt_log_slow_admin_statements is set.
861 */
862 thd->enable_slow_log= TRUE;
863+ thd->clear_slow_extended();
864 thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
865 thd->set_time();
866 if (!thd->is_valid_time())
867@@ -1430,6 +1432,60 @@
735 DBUG_RETURN(error);868 DBUG_RETURN(error);
736 }869 }
737 870
@@ -792,7 +925,7 @@
792 925
793 void log_slow_statement(THD *thd)926 void log_slow_statement(THD *thd)
794 {927 {
795@@ -1443,13 +1498,48 @@928@@ -1443,13 +1499,48 @@
796 if (unlikely(thd->in_sub_stmt))929 if (unlikely(thd->in_sub_stmt))
797 DBUG_VOID_RETURN; // Don't set time for sub stmt930 DBUG_VOID_RETURN; // Don't set time for sub stmt
798 931
@@ -842,38 +975,16 @@
842 thd_proc_info(thd, "logging slow query");975 thd_proc_info(thd, "logging slow query");
843 976
844 if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||977 if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
845@@ -1879,6 +1969,9 @@978@@ -5295,7 +5386,8 @@
846 context.resolve_in_table_list_only(select_lex->979 thd->stmt_da->reset_diagnostics_area();
847 table_list.first);980 thd->warning_info->reset_for_next_command();
848
849+ /* Reset the counter at all cases for the extended slow query log */
850+ thd->sent_row_count= 0;
851+
852 /*
853 Reset warning count for each query that uses tables
854 A better approach would be to reset this for any commands
855@@ -5297,6 +5390,21 @@
856 thd->rand_used= 0;981 thd->rand_used= 0;
857 thd->sent_row_count= thd->examined_row_count= 0;982- thd->sent_row_count= thd->examined_row_count= 0;
983+
984+ thd->clear_slow_extended();
858 985
859+ thd->bytes_sent_old= thd->status_var.bytes_sent;
860+ thd->tmp_tables_used= thd->tmp_tables_disk_used= 0;
861+ thd->tmp_tables_size= 0;
862+ thd->innodb_was_used= FALSE;
863+ thd->innodb_trx_id= 0;
864+ thd->innodb_io_reads= 0;
865+ thd->innodb_io_read= 0;
866+ thd->innodb_io_reads_wait_timer= 0;
867+ thd->innodb_lock_que_wait_timer= 0;
868+ thd->innodb_innodb_que_wait_timer= 0;
869+ thd->innodb_page_access= 0;
870+ thd->query_plan_flags= QPLAN_NONE;
871+ thd->query_plan_fsort_passes= 0;
872+ thd->last_errno= 0;
873+
874 thd->reset_current_stmt_binlog_format_row();986 thd->reset_current_stmt_binlog_format_row();
875 thd->binlog_unsafe_warning_flags= 0;987 thd->binlog_unsafe_warning_flags= 0;
876
877--- a/sql/sql_select.cc988--- a/sql/sql_select.cc
878+++ b/sql/sql_select.cc989+++ b/sql/sql_select.cc
879@@ -6902,7 +6902,10 @@990@@ -6902,7 +6902,10 @@
@@ -2425,6 +2536,7 @@
2425+--let grep_pattern = Last_errno: 10502536+--let grep_pattern = Last_errno: 1050
2426+--source include/log_grep.inc2537+--source include/log_grep.inc
2427+DROP TABLE t;2538+DROP TABLE t;
2539<<<<<<< TREE
2428--- /dev/null2540--- /dev/null
2429+++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_basic.test2541+++ b/mysql-test/suite/sys_vars/t/log_slow_admin_statements_basic.test
2430@@ -0,0 +1 @@2542@@ -0,0 +1 @@
@@ -2574,3 +2686,322 @@
2574@@ -0,0 +1,2 @@2686@@ -0,0 +1,2 @@
2575+SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';2687+SHOW GLOBAL VARIABLES like 'log_slow_admin_statements';
2576+SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';2688+SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME='log_slow_admin_statements';
2689=======
2690--- /dev/null
2691+++ b/mysql-test/t/percona_slow_extended_error_on_quit.test
2692@@ -0,0 +1,87 @@
2693+################################################################################
2694+# Current test check following attributes: #
2695+# 1) "Last_errno" #
2696+# 2) "Rows_{sent,examined|affected|read} #
2697+# 3) Bytes_sent #
2698+# 4) Tmp_{tables|dist_tables|table_size} #
2699+# 5) InnoDB statistic counters #
2700+# in Slow Query Log #
2701+# for administrative command "Quit" #
2702+# #
2703+# See Launchpad Bug #716210 #
2704+################################################################################
2705+
2706+--source include/have_innodb.inc
2707+
2708+################################################################################
2709+--let log_file=percona.slow_extended.error_on_quit
2710+--let wait_condition=SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST;
2711+################################################################################
2712+
2713+--disable_warnings
2714+DROP TABLE IF EXISTS t;
2715+--enable_warnings
2716+CREATE TABLE t(a INT) engine=InnoDB;
2717+INSERT INTO t VALUES(0),(1),(2),(3),(4);
2718+
2719+################################################################################
2720+--source include/log_start.inc
2721+
2722+--connect(additional,localhost,root,,)
2723+--connection additional
2724+
2725+ SET log_slow_verbosity=innodb;
2726+ SET long_query_time= 0;
2727+
2728+--disable_result_log
2729+--error ER_TABLE_EXISTS_ERROR
2730+ CREATE TABLE t(a INT) engine=InnoDB;
2731+--enable_result_log
2732+
2733+--connection default
2734+--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
2735+--disconnect additional
2736+--source include/wait_condition.inc
2737+--source include/log_stop.inc
2738+--source include/percona_slow_extended_error_on_quit.inc
2739+################################################################################
2740+--source include/log_start.inc
2741+
2742+--connect(additional,localhost,root,,)
2743+--connection additional
2744+
2745+ SET log_slow_verbosity=innodb;
2746+ SET long_query_time= 0;
2747+
2748+--disable_result_log
2749+ INSERT INTO t SELECT * FROM t ORDER BY RAND();
2750+--enable_result_log
2751+
2752+--connection default
2753+--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
2754+--disconnect additional
2755+--source include/wait_condition.inc
2756+--source include/log_stop.inc
2757+--source include/percona_slow_extended_error_on_quit.inc
2758+################################################################################
2759+--source include/log_start.inc
2760+
2761+--connect(additional,localhost,root,,)
2762+--connection additional
2763+
2764+ SET log_slow_verbosity=innodb;
2765+ SET long_query_time= 0;
2766+
2767+--disable_result_log
2768+ SELECT * FROM t;
2769+--enable_result_log
2770+
2771+--connection default
2772+--echo # Disconnecting (passing to Slow Query Log "# administrative command: Quit")
2773+--disconnect additional
2774+--source include/wait_condition.inc
2775+--source include/log_stop.inc
2776+--source include/percona_slow_extended_error_on_quit.inc
2777+################################################################################
2778+
2779+DROP TABLE t;
2780--- /dev/null
2781+++ b/mysql-test/r/percona_slow_extended_error_on_quit.result
2782@@ -0,0 +1,171 @@
2783+DROP TABLE IF EXISTS t;
2784+CREATE TABLE t(a INT) engine=InnoDB;
2785+INSERT INTO t VALUES(0),(1),(2),(3),(4);
2786+[log_start.inc] percona.slow_extended.error_on_quit
2787+SET log_slow_verbosity=innodb;
2788+SET long_query_time= 0;
2789+CREATE TABLE t(a INT) engine=InnoDB;
2790+# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
2791+[log_stop.inc] percona.slow_extended.error_on_quit
2792+################################################################################
2793+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
2794+[log_grep.inc] lines: 1
2795+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
2796+[log_grep.inc] lines: 0
2797+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
2798+[log_grep.inc] lines: 0
2799+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
2800+[log_grep.inc] lines: 1
2801+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
2802+[log_grep.inc] lines: 1
2803+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
2804+[log_grep.inc] lines: 2
2805+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
2806+[log_grep.inc] lines: 0
2807+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
2808+[log_grep.inc] lines: 3
2809+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
2810+[log_grep.inc] lines: 0
2811+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
2812+[log_grep.inc] lines: 3
2813+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
2814+[log_grep.inc] lines: 0
2815+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
2816+[log_grep.inc] lines: 3
2817+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
2818+[log_grep.inc] lines: 0
2819+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
2820+[log_grep.inc] lines: 3
2821+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
2822+[log_grep.inc] lines: 2
2823+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
2824+[log_grep.inc] lines: 1
2825+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
2826+[log_grep.inc] lines: 0
2827+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
2828+[log_grep.inc] lines: 3
2829+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
2830+[log_grep.inc] lines: 0
2831+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
2832+[log_grep.inc] lines: 3
2833+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
2834+[log_grep.inc] lines: 0
2835+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
2836+[log_grep.inc] lines: 3
2837+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
2838+[log_grep.inc] lines: 2
2839+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id:
2840+[log_grep.inc] lines: 1
2841+################################################################################
2842+[log_start.inc] percona.slow_extended.error_on_quit
2843+SET log_slow_verbosity=innodb;
2844+SET long_query_time= 0;
2845+INSERT INTO t SELECT * FROM t ORDER BY RAND();
2846+# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
2847+[log_stop.inc] percona.slow_extended.error_on_quit
2848+################################################################################
2849+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
2850+[log_grep.inc] lines: 0
2851+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
2852+[log_grep.inc] lines: 1
2853+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
2854+[log_grep.inc] lines: 1
2855+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
2856+[log_grep.inc] lines: 1
2857+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
2858+[log_grep.inc] lines: 0
2859+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
2860+[log_grep.inc] lines: 3
2861+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
2862+[log_grep.inc] lines: 0
2863+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
2864+[log_grep.inc] lines: 3
2865+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
2866+[log_grep.inc] lines: 1
2867+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
2868+[log_grep.inc] lines: 2
2869+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
2870+[log_grep.inc] lines: 2
2871+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
2872+[log_grep.inc] lines: 1
2873+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
2874+[log_grep.inc] lines: 0
2875+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
2876+[log_grep.inc] lines: 3
2877+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
2878+[log_grep.inc] lines: 2
2879+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
2880+[log_grep.inc] lines: 1
2881+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
2882+[log_grep.inc] lines: 1
2883+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
2884+[log_grep.inc] lines: 2
2885+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
2886+[log_grep.inc] lines: 0
2887+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
2888+[log_grep.inc] lines: 3
2889+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
2890+[log_grep.inc] lines: 1
2891+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
2892+[log_grep.inc] lines: 2
2893+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
2894+[log_grep.inc] lines: 2
2895+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id:
2896+[log_grep.inc] lines: 1
2897+################################################################################
2898+[log_start.inc] percona.slow_extended.error_on_quit
2899+SET log_slow_verbosity=innodb;
2900+SET long_query_time= 0;
2901+SELECT * FROM t;
2902+# Disconnecting (passing to Slow Query Log "# administrative command: Quit")
2903+[log_stop.inc] percona.slow_extended.error_on_quit
2904+################################################################################
2905+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: CREATE
2906+[log_grep.inc] lines: 0
2907+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: INSERT
2908+[log_grep.inc] lines: 0
2909+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: SELECT
2910+[log_grep.inc] lines: 1
2911+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Quit
2912+[log_grep.inc] lines: 1
2913+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: [^0]+
2914+[log_grep.inc] lines: 0
2915+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Last_errno: 0
2916+[log_grep.inc] lines: 3
2917+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: [^0]+
2918+[log_grep.inc] lines: 1
2919+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_sent: 0
2920+[log_grep.inc] lines: 2
2921+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: [^0]+
2922+[log_grep.inc] lines: 1
2923+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_examined: 0
2924+[log_grep.inc] lines: 2
2925+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: [^0]+
2926+[log_grep.inc] lines: 0
2927+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_affected: 0
2928+[log_grep.inc] lines: 3
2929+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: [^0]+
2930+[log_grep.inc] lines: 1
2931+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Rows_read: 0
2932+[log_grep.inc] lines: 2
2933+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: [^0]+
2934+[log_grep.inc] lines: 2
2935+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Bytes_sent: 0
2936+[log_grep.inc] lines: 1
2937+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: [^0]+
2938+[log_grep.inc] lines: 0
2939+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_tables: 0
2940+[log_grep.inc] lines: 3
2941+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: [^0]+
2942+[log_grep.inc] lines: 0
2943+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_disk_tables: 0
2944+[log_grep.inc] lines: 3
2945+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: [^0]+
2946+[log_grep.inc] lines: 0
2947+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: Tmp_table_sizes: 0
2948+[log_grep.inc] lines: 3
2949+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # No InnoDB statistics available for this query
2950+[log_grep.inc] lines: 2
2951+[log_grep.inc] file: percona.slow_extended.error_on_quit pattern: # InnoDB_trx_id:
2952+[log_grep.inc] lines: 1
2953+################################################################################
2954--- /dev/null
2955+++ b/mysql-test/include/percona_slow_extended_error_on_quit.inc
2956@@ -0,0 +1,50 @@
2957+--echo ################################################################################
2958+--let grep_pattern=CREATE
2959+--source include/log_grep.inc
2960+--let grep_pattern=INSERT
2961+--source include/log_grep.inc
2962+--let grep_pattern=SELECT
2963+--source include/log_grep.inc
2964+--let grep_pattern=Quit
2965+--source include/log_grep.inc
2966+--let grep_pattern=Last_errno: [^0]+
2967+--source include/log_grep.inc
2968+--let grep_pattern=Last_errno: 0
2969+--source include/log_grep.inc
2970+--let grep_pattern=Rows_sent: [^0]+
2971+--source include/log_grep.inc
2972+--let grep_pattern=Rows_sent: 0
2973+--source include/log_grep.inc
2974+--let grep_pattern=Rows_examined: [^0]+
2975+--source include/log_grep.inc
2976+--let grep_pattern=Rows_examined: 0
2977+--source include/log_grep.inc
2978+--let grep_pattern=Rows_affected: [^0]+
2979+--source include/log_grep.inc
2980+--let grep_pattern=Rows_affected: 0
2981+--source include/log_grep.inc
2982+--let grep_pattern=Rows_read: [^0]+
2983+--source include/log_grep.inc
2984+--let grep_pattern=Rows_read: 0
2985+--source include/log_grep.inc
2986+--let grep_pattern=Bytes_sent: [^0]+
2987+--source include/log_grep.inc
2988+--let grep_pattern=Bytes_sent: 0
2989+--source include/log_grep.inc
2990+--let grep_pattern=Tmp_tables: [^0]+
2991+--source include/log_grep.inc
2992+--let grep_pattern=Tmp_tables: 0
2993+--source include/log_grep.inc
2994+--let grep_pattern=Tmp_disk_tables: [^0]+
2995+--source include/log_grep.inc
2996+--let grep_pattern=Tmp_disk_tables: 0
2997+--source include/log_grep.inc
2998+--let grep_pattern=Tmp_table_sizes: [^0]+
2999+--source include/log_grep.inc
3000+--let grep_pattern=Tmp_table_sizes: 0
3001+--source include/log_grep.inc
3002+--let grep_pattern=# No InnoDB statistics available for this query
3003+--source include/log_grep.inc
3004+--let grep_pattern=# InnoDB_trx_id:
3005+--source include/log_grep.inc
3006+--echo ################################################################################
3007>>>>>>> MERGE-SOURCE

Subscribers

People subscribed via source and target branches