« back to all changes in this revision
Viewing changes to patches/slow_extended.patch
- browse files at revision 197
- compare with another revision
- download diff
- download tarball
- view history from revision 197
- Committer: Oleg Tsarev
- Date: 2011-11-22 18:31:50 UTC
- mfrom: (187.2.2 5.5_fix_bug_716210_3)
- Revision ID: oleg.tsarev@percona.com-20111122183150-f8jmsgbtcvmerhdt
merge fix for #716210
- files modified:
- patches/slow_extended.patch
added
removed
patches/slow_extended.patch
227
227
}
228
228
else
229
229
{
230
@@ -1239,8 +1255,20 @@
231
query_length= command_name[thd->command].length;
230
@@ -1240,7 +1256,7 @@
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
233
for (current_handler= slow_log_handler_list; *current_handler ;)
247
234
- error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
248
235
+ error= (*current_handler++)->log_slow(thd, current_utime, thd->start_time,
249
236
user_host_buff, user_host_len,
250
237
query_utime, lock_utime, is_command,
251
238
query, query_length) || error;
252
@@ -2656,12 +2684,13 @@
239
@@ -2656,12 +2672,13 @@
253
240
TRUE - error occured
254
241
*/
255
242
264
251
bool error= 0;
265
252
DBUG_ENTER("MYSQL_QUERY_LOG::write");
266
253
267
@@ -2683,17 +2712,28 @@
254
@@ -2683,17 +2700,28 @@
268
255
269
256
if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
270
257
{
300
287
301
288
/* Note that my_b_write() assumes it knows the length for this */
302
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
292
sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
305
293
sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0);
294
+ DBUG_PRINT("info", ("Last_errno: %u", thd->last_errno));
306
295
if (my_b_printf(&log_file,
307
296
- "# Query_time: %s Lock_time: %s"
308
297
- " Rows_sent: %lu Rows_examined: %lu\n",
521
510
522
511
+extern "C"
523
512
+void increment_thd_innodb_stats(THD* thd,
524
+ unsigned long long trx_id,
525
+ long io_reads,
526
+ long long io_read,
527
+ long io_reads_wait_timer,
528
+ long lock_que_wait_timer,
529
+ long que_wait_timer,
530
+ long page_access)
513
+ unsigned long long trx_id,
514
+ long io_reads,
515
+ long long io_read,
516
+ long io_reads_wait_timer,
517
+ long lock_que_wait_timer,
518
+ long que_wait_timer,
519
+ long page_access)
531
520
+{
532
+ thd->innodb_was_used = TRUE;
533
+ thd->innodb_trx_id = trx_id;
534
+ thd->innodb_io_reads += io_reads;
535
+ thd->innodb_io_read += io_read;
536
+ thd->innodb_io_reads_wait_timer += io_reads_wait_timer;
537
+ thd->innodb_lock_que_wait_timer += lock_que_wait_timer;
538
+ thd->innodb_innodb_que_wait_timer += que_wait_timer;
539
+ thd->innodb_page_access += page_access;
521
+ thd->innodb_was_used= TRUE;
522
+ thd->innodb_trx_id= trx_id;
523
+ thd->innodb_io_reads+= io_reads;
524
+ thd->innodb_io_read+= io_read;
525
+ thd->innodb_io_reads_wait_timer+= io_reads_wait_timer;
526
+ thd->innodb_lock_que_wait_timer+= lock_que_wait_timer;
527
+ thd->innodb_innodb_que_wait_timer+= que_wait_timer;
528
+ thd->innodb_page_access+= page_access;
540
529
+}
541
530
+
542
531
+extern "C"
553
542
554
543
/**
555
544
Dumps a text description of a thread, its security context
556
@@ -926,6 +957,8 @@
545
@@ -942,6 +973,8 @@
557
546
const char* msg,
558
547
MYSQL_ERROR ** cond_hdl)
559
548
{
562
551
if (!m_internal_handler)
563
552
{
564
553
*cond_hdl= NULL;
565
@@ -3675,6 +3708,12 @@
554
@@ -1236,6 +1269,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
@@ -3682,8 +3717,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
@@ -3691,6 +3724,7 @@
566
573
first_successful_insert_id_in_prev_stmt;
567
574
backup->first_successful_insert_id_in_cur_stmt=
568
575
first_successful_insert_id_in_cur_stmt;
569
+ backup->innodb_io_reads= innodb_io_reads;
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;
576
+ reset_sub_statement_state_slow_extended(backup);
575
577
576
578
if ((!lex->requires_prelocking() || is_update_query(lex->sql_command)) &&
577
579
!is_current_stmt_binlog_format_row())
578
@@ -3695,6 +3734,14 @@
580
@@ -3706,13 +3740,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
586
cuted_fields= 0;
580
587
transaction.savepoints= 0;
581
588
first_successful_insert_id_in_cur_stmt= 0;
582
+ last_errno= 0;
583
+ innodb_trx_id= 0;
584
+ innodb_io_reads= 0;
585
+ innodb_io_read= 0;
586
+ innodb_io_reads_wait_timer= 0;
587
+ innodb_lock_que_wait_timer= 0;
589
}
590
591
+void THD::clear_slow_extended()
592
+{
593
+ DBUG_ENTER("THD::clear_slow_extended");
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
606
+ innodb_innodb_que_wait_timer= 0;
589
+ innodb_page_access= 0;
590
}
591
592
593
@@ -3757,6 +3804,12 @@
607
+ innodb_page_access= 0;
608
+ query_plan_flags= QPLAN_NONE;
609
+ query_plan_fsort_passes= 0;
610
+ last_errno= 0;
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(const 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
@@ -3753,7 +3848,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
@@ -3771,8 +3865,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
670
cuted_fields+= backup->cuted_fields;
597
+ innodb_io_reads+= backup->innodb_io_reads;
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;
671
+ restore_sub_statement_state_slow_extended(backup);
603
672
DBUG_VOID_RETURN;
604
673
}
605
674
661
730
double long_query_time_double;
662
731
663
732
} SV;
664
@@ -1140,6 +1182,14 @@
733
@@ -1140,6 +1182,24 @@
665
734
uint in_sub_stmt;
666
735
bool enable_slow_log;
667
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
744
+ ulong innodb_io_reads;
670
745
+ ulonglong innodb_io_read;
671
746
+ ulong innodb_io_reads_wait_timer;
673
748
+ ulong innodb_innodb_que_wait_timer;
674
749
+ ulong innodb_page_access;
675
750
+
751
+ ulong query_plan_flags;
752
+ ulong query_plan_fsort_passes;
753
+ /*** The variables above used in slow_extended.patch ***/
754
+
676
755
SAVEPOINT *savepoints;
677
756
enum enum_check_fields count_cuted_fields;
678
757
};
679
@@ -1588,6 +1638,26 @@
758
@@ -1588,6 +1648,71 @@
680
759
thr_lock_type update_lock_default;
681
760
Delayed_insert *di;
682
761
762
+ /*** Following variables used in slow_extended.patch ***/
763
+ /*
764
+ Variable write_to_slow_log:
765
+ 1) initialized in
766
+ * sql_connect.cc (log_slow_rate_limit support)
767
+ * slave.cc (log_slow_slave_statements support)
768
+ 2) The variable is initialized on the thread startup and remains
769
+ constant afterwards. This will change when
770
+ LP #712396 ("log_slow_slave_statements not work on replication
771
+ threads without RESTART") is implemented.
772
+ 3) An implementation of LP #688646 ("Make query sampling possible by query") should use it.
773
+ */
683
774
+ bool write_to_slow_log;
684
+
775
+ /*
776
+ Variable bytes_send_old saves value of thd->status_var.bytes_sent
777
+ before query execution.
778
+ */
685
779
+ ulonglong bytes_sent_old;
780
+ /*
781
+ Variables tmp_tables_*** collect statistics about usage of temporary tables
782
+ */
686
783
+ ulong tmp_tables_used;
687
784
+ ulong tmp_tables_disk_used;
688
785
+ ulonglong tmp_tables_size;
786
+ /*
787
+ Variable innodb_was_used shows used or not InnoDB engine in current query.
788
+ */
689
789
+ bool innodb_was_used;
790
+ /*
791
+ Following Variables innodb_*** (is |should be) different from
792
+ default values only if (innodb_was_used==TRUE)
793
+ */
690
794
+ ulonglong innodb_trx_id;
691
795
+ ulong innodb_io_reads;
692
796
+ ulonglong innodb_io_read;
695
799
+ ulong innodb_innodb_que_wait_timer;
696
800
+ ulong innodb_page_access;
697
801
+
802
+ /*
803
+ Variable query_plan_flags collects information about query plan entites
804
+ used on query execution.
805
+ */
698
806
+ ulong query_plan_flags;
807
+ /*
808
+ Variable query_plan_fsort_passes collects information about file sort passes
809
+ acquired during query execution.
810
+ */
699
811
+ ulong query_plan_fsort_passes;
700
+
812
+ /*
813
+ Query can generate several errors/warnings during execution
814
+ (see THD::handle_condition comment in sql_class.h)
815
+ Variable last_errno contains the last error/warning acquired during
816
+ query execution.
817
+ */
701
818
+ uint last_errno;
819
+ /*** The variables above used in slow_extended.patch ***/
820
+
821
+ /*** Following methods used in slow_extended.patch ***/
822
+ void clear_slow_extended();
823
+ void reset_sub_statement_state_slow_extended(Sub_statement_state *backup);
824
+ void restore_sub_statement_state_slow_extended(const Sub_statement_state *backup);
825
+ /*** The methods above used in slow_extended.patch ***/
702
826
+
703
827
/* <> 0 if we are inside of trigger or stored function. */
704
828
uint in_sub_stmt;
731
855
732
856
const char *any_db="*any*"; // Special symbol for check_access
733
857
734
@@ -1430,6 +1431,60 @@
858
@@ -888,6 +889,7 @@
859
the slow log only if opt_log_slow_admin_statements is set.
860
*/
861
thd->enable_slow_log= TRUE;
862
+ thd->clear_slow_extended();
863
thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
864
thd->set_time();
865
if (!thd->is_valid_time())
866
@@ -1430,6 +1432,60 @@
735
867
DBUG_RETURN(error);
736
868
}
737
869
792
924
793
925
void log_slow_statement(THD *thd)
794
926
{
795
@@ -1443,13 +1498,48 @@
927
@@ -1443,13 +1499,48 @@
796
928
if (unlikely(thd->in_sub_stmt))
797
929
DBUG_VOID_RETURN; // Don't set time for sub stmt
798
930
842
974
thd_proc_info(thd, "logging slow query");
843
975
844
976
if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
845
@@ -1879,6 +1969,9 @@
846
context.resolve_in_table_list_only(select_lex->
847
table_list.first);
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
@@ -5303,6 +5396,21 @@
977
@@ -5301,7 +5392,8 @@
978
thd->stmt_da->reset_diagnostics_area();
979
thd->warning_info->reset_for_next_command();
856
980
thd->rand_used= 0;
857
thd->sent_row_count= thd->examined_row_count= 0;
981
- thd->sent_row_count= thd->examined_row_count= 0;
982
+
983
+ thd->clear_slow_extended();
858
984
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
985
thd->reset_current_stmt_binlog_format_row();
875
986
thd->binlog_unsafe_warning_flags= 0;
876
877
987
--- a/sql/sql_select.cc
878
988
+++ b/sql/sql_select.cc
879
989
@@ -6902,7 +6902,10 @@
Loggerhead is a web-based interface for Breezy
Version: 2.0.1