percona/percona-toolkit
1
0
Fork 0
mirror of https://github.com/percona/percona-toolkit.git synced 2025-10-21 18:24:38 +00:00
Code Issues Packages Projects Releases Wiki Activity

Combine '# Log_slow_rate_type: query Log_slow_rate_limit: 2' as 'query:2' and report as 'rate_limit' metric.

Browse Source
This commit is contained in:
Daniel Nichter
2013-11-27 18:25:55 -08:00
parent a84fab30c8
commit c178934ab1
6 changed files with 211 additions and 3 deletions
Download Patch File Download Diff File Expand all files Collapse all files

24
bin/pt-query-digest
View File

@@ -6776,6 +6776,10 @@ sub header {
push @result, "# Time range: $time_range"; push @result, "# Time range: $time_range";
} }
if ( $results->{globals}->{rate_limit} ) {
print "# Rate limits apply\n";
}
push @result, $self->make_global_header(); push @result, $self->make_global_header();
my $attribs = $self->sort_attribs( $ea ); my $attribs = $self->sort_attribs( $ea );
@@ -6788,7 +6792,6 @@ sub header {
NUM_ATTRIB: NUM_ATTRIB:
foreach my $attrib ( @{$attribs->{$type}} ) { foreach my $attrib ( @{$attribs->{$type}} ) {
next unless exists $results->{globals}->{$attrib}; next unless exists $results->{globals}->{$attrib};
my $store = $results->{globals}->{$attrib}; my $store = $results->{globals}->{$attrib};
my $metrics = $ea->stats()->{globals}->{$attrib}; my $metrics = $ea->stats()->{globals}->{$attrib};
my $func = $attrib =~ m/time|wait$/ ? \&micro_t : \&shorten; my $func = $attrib =~ m/time|wait$/ ? \&micro_t : \&shorten;
@@ -13999,6 +14002,24 @@ sub main {
); );
} # print } # print
# Combine "# Log_slow_rate_type: query Log_slow_rate_limit: 2"
# as rate_limit=>'query:2'.
$pipeline->add(
name => 'rate limit',
process => sub {
my ( $args ) = @_;
my $event = $args->{event};
PTDEBUG && _d('callback: rate limit');
if ( my $limit = $event->{Log_slow_rate_limit} ) {
$event->{rate_limit} = ($event->{Log_slow_rate_type} || 'session') . ":$limit";
delete $event->{Log_slow_rate_limit};
delete $event->{Log_slow_rate_type};
}
return $args;
},
);
# Finally, add aggregator obj for each groupby attrib to the callbacks. # Finally, add aggregator obj for each groupby attrib to the callbacks.
# These aggregating objs should be the last pipeline processes. # These aggregating objs should be the last pipeline processes.
foreach my $i ( 0..$#groupby ) { foreach my $i ( 0..$#groupby ) {
@@ -14024,6 +14045,7 @@ sub main {
ip => 'string', ip => 'string',
port => 'string', port => 'string',
Killed => 'bool', Killed => 'bool',
rate_limit => 'string',
}; };
my $ea = new EventAggregator( my $ea = new EventAggregator(

1
lib/PerconaTest.pm
View File

@@ -39,6 +39,7 @@ use Test::More;
use Time::HiRes qw(sleep time); use Time::HiRes qw(sleep time);
use File::Temp qw(tempfile); use File::Temp qw(tempfile);
use POSIX qw(signal_h); use POSIX qw(signal_h);
use Data::Dumper;
require Exporter; require Exporter;
our @ISA = qw(Exporter); our @ISA = qw(Exporter);

8
lib/QueryReportFormatter.pm
View File

@@ -272,6 +272,11 @@ sub header {
push @result, "# Time range: $time_range"; push @result, "# Time range: $time_range";
} }
# Third line: rate limiting, if any
if ( $results->{globals}->{rate_limit} ) {
print "# Rate limits apply\n";
}
# Global column headers # Global column headers
push @result, $self->make_global_header(); push @result, $self->make_global_header();
@@ -287,7 +292,6 @@ sub header {
NUM_ATTRIB: NUM_ATTRIB:
foreach my $attrib ( @{$attribs->{$type}} ) { foreach my $attrib ( @{$attribs->{$type}} ) {
next unless exists $results->{globals}->{$attrib}; next unless exists $results->{globals}->{$attrib};
my $store = $results->{globals}->{$attrib}; my $store = $results->{globals}->{$attrib};
my $metrics = $ea->stats()->{globals}->{$attrib}; my $metrics = $ea->stats()->{globals}->{$attrib};
my $func = $attrib =~ m/time|wait$/ ? \&micro_t : \&shorten; my $func = $attrib =~ m/time|wait$/ ? \&micro_t : \&shorten;
@@ -684,7 +688,7 @@ sub event_report {
push @result, push @result,
sprintf("# Scores: V/M = %.2f", $val->{variance_to_mean} ); sprintf("# Scores: V/M = %.2f", $val->{variance_to_mean} );
# Last line before column headers: time range # Time range
if ( $val->{time_range} ) { if ( $val->{time_range} ) {
push @result, "# Time range: $val->{time_range}"; push @result, "# Time range: $val->{time_range}";
} }

40
t/lib/samples/slowlogs/slow059.txt Normal file
View File

@@ -0,0 +1,40 @@
# Time: 131128 1:05:31
# User@Host: user1[user1] @ localhost [127.0.0.1] Id: 69194
# Schema: maindb Last_errno: 0 Killed: 0
# Query_time: 0.000228 Lock_time: 0.000114 Rows_sent: 1 Rows_examined: 1 Rows_affected: 0
# Bytes_sent: 545 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 1A88583F
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 2
# Log_slow_rate_type: query Log_slow_rate_limit: 2
SET timestamp=1385600731;
SELECT foo FROM bar WHERE id=1;
# User@Host: user1[user1] @ localhost [127.0.0.1] Id: 69195
# Schema: maindb Last_errno: 0 Killed: 0
# Query_time: 0.000237 Lock_time: 0.000122 Rows_sent: 1 Rows_examined: 1 Rows_affected: 0
# Bytes_sent: 545 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 1A885840
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 2
# Log_slow_rate_type: query Log_slow_rate_limit: 2
SET timestamp=1385600731;
SELECT foo FROM bar WHERE id=2;
# User@Host: user1[user1] @ localhost [127.0.0.1] Id: 69195
# Schema: maindb Last_errno: 0 Killed: 0
# Query_time: 0.000165 Lock_time: 0.000048 Rows_sent: 5 Rows_examined: 10 Rows_affected: 0
# Bytes_sent: 481 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 1A885842
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: Yes Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 3
# Log_slow_rate_type: query Log_slow_rate_limit: 2
SET timestamp=1385600731;
INSERT INTO foo VALUES (NULL, 3);

127
t/pt-query-digest/samples/slow059_report01.txt Normal file
View File

@@ -0,0 +1,127 @@
# Rate limits apply
# Overall: 3 total, 2 unique, 0 QPS, 0x concurrency ______________________
# Time range: all events occurred at 2013-11-28 01:05:31
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 630us 165us 237us 210us 236us 33us 224us
# Lock time 284us 48us 122us 94us 119us 32us 113us
# Rows sent 7 1 5 2.33 4.96 1.87 0.99
# Rows examine 12 1 10 4 9.83 4.17 0.99
# Rows affecte 0 0 0 0 0 0 0
# Bytes sent 1.53k 481 545 523.67 537.02 32 537.02
# Merge passes 0 0 0 0 0 0 0
# Tmp tables 0 0 0 0 0 0 0
# Tmp disk tbl 0 0 0 0 0 0 0
# Tmp tbl size 0 0 0 0 0 0 0
# Query size 92 30 32 30.67 31.70 1 28.75
# InnoDB:
# IO r bytes 0 0 0 0 0 0 0
# IO r ops 0 0 0 0 0 0 0
# IO r wait 0 0 0 0 0 0 0
# pages distin 7 2 3 2.33 2.90 0.44 1.96
# queue wait 0 0 0 0 0 0 0
# rec lock wai 0 0 0 0 0 0 0
# Boolean:
# Filesort 33% yes, 66% no
# Query 1: 0 QPS, 0x concurrency, ID 0x9EA505F4786E7F15 at byte 733 ______
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2013-11-28 01:05:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 66 2
# Exec time 73 465us 228us 237us 232us 237us 6us 232us
# Lock time 83 236us 114us 122us 118us 122us 5us 118us
# Rows sent 28 2 1 1 1 1 0 1
# Rows examine 16 2 1 1 1 1 0 1
# Rows affecte 0 0 0 0 0 0 0 0
# Bytes sent 69 1.06k 545 545 545 545 0 545
# Merge passes 0 0 0 0 0 0 0 0
# Tmp tables 0 0 0 0 0 0 0 0
# Tmp disk tbl 0 0 0 0 0 0 0 0
# Tmp tbl size 0 0 0 0 0 0 0 0
# Query size 65 60 30 30 30 30 0 30
# InnoDB:
# IO r bytes 0 0 0 0 0 0 0 0
# IO r ops 0 0 0 0 0 0 0 0
# IO r wait 0 0 0 0 0 0 0 0
# pages distin 57 4 2 2 2 2 0 2
# queue wait 0 0 0 0 0 0 0 0
# rec lock wai 0 0 0 0 0 0 0 0
# String:
# Databases maindb
# Hosts localhost
# InnoDB trxID 1A88583F (1/50%), 1A885840 (1/50%)
# Last errno 0
# rate limit query:2
# Users user1
# Query_time distribution
# 1us
# 10us
# 100us ################################################################
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `maindb` LIKE 'bar'\G
# SHOW CREATE TABLE `maindb`.`bar`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT foo FROM bar WHERE id=2\G
# Query 2: 0 QPS, 0x concurrency, ID 0xD2BA209E593ABAA7 at byte 1441 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2013-11-28 01:05:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 33 1
# Exec time 26 165us 165us 165us 165us 165us 0 165us
# Lock time 16 48us 48us 48us 48us 48us 0 48us
# Rows sent 71 5 5 5 5 5 0 5
# Rows examine 83 10 10 10 10 10 0 10
# Rows affecte 0 0 0 0 0 0 0 0
# Bytes sent 30 481 481 481 481 481 0 481
# Merge passes 0 0 0 0 0 0 0 0
# Tmp tables 0 0 0 0 0 0 0 0
# Tmp disk tbl 0 0 0 0 0 0 0 0
# Tmp tbl size 0 0 0 0 0 0 0 0
# Query size 34 32 32 32 32 32 0 32
# InnoDB:
# IO r bytes 0 0 0 0 0 0 0 0
# IO r ops 0 0 0 0 0 0 0 0
# IO r wait 0 0 0 0 0 0 0 0
# pages distin 42 3 3 3 3 3 0 3
# queue wait 0 0 0 0 0 0 0 0
# rec lock wai 0 0 0 0 0 0 0 0
# Boolean:
# Filesort 100% yes, 0% no
# String:
# Databases maindb
# Hosts localhost
# InnoDB trxID 1A885842
# Last errno 0
# rate limit query:2
# Users user1
# Query_time distribution
# 1us
# 10us
# 100us ################################################################
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `maindb` LIKE 'foo'\G
# SHOW CREATE TABLE `maindb`.`foo`\G
INSERT INTO foo VALUES (NULL, 3)\G
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ==========
# 1 0x9EA505F4786E7F15 0.0005 73.8% 2 0.0002 0.00 SELECT bar
# 2 0xD2BA209E593ABAA7 0.0002 26.2% 1 0.0002 0.00 INSERT foo

14
t/pt-query-digest/slowlog_analyses.t
View File

@@ -423,6 +423,20 @@ ok(
'Analysis for slow058 (bug 821692, bug 984053)' 'Analysis for slow058 (bug 821692, bug 984053)'
) or diag($test_diff); ) or diag($test_diff);
# #############################################################################
# pt-query-digest support for Percona Server slow log rate limiting
# https://blueprints.launchpad.net/percona-toolkit/+spec/pt-query-digest-rate-limit
# #############################################################################
ok(
no_diff(
sub { pt_query_digest::main(@args, $sample.'slow059.txt',
'--report-format', 'header,query_report,profile')
},
"t/pt-query-digest/samples/slow059_report01.txt"
),
'Analysis for slow059 with rate limiting'
) or diag($test_diff);
# ############################################################################# # #############################################################################
# Done. # Done.
# ############################################################################# # #############################################################################