PT-234 Fixed general log parser for timestamps having timezone

This commit is contained in:
Carlos Salguero
2017-12-19 12:50:35 -03:00
parent 3239ce8e3e
commit e1275a6c67
6 changed files with 148 additions and 3 deletions

View File

@@ -9898,7 +9898,7 @@ sub new {
my $genlog_line_1= qr{
\A
(?:(\d{6}\s+\d{1,2}:\d\d:\d\d|\d{4}-\d{1,2}-\d{1,2}T\d\d:\d\d:\d\d\.\d+Z))? # Timestamp
(?:(\d{6}\s+\d{1,2}:\d\d:\d\d|\d{4}-\d{1,2}-\d{1,2}T\d\d:\d\d:\d\d\.\d+(?:Z|-?\d\d:\d\d)?))? # Timestamp
\s+
(?:\s*(\d+)) # Thread ID
\s

View File

@@ -6889,7 +6889,7 @@ sub new {
my $genlog_line_1= qr{
\A
(?:(\d{6}\s+\d{1,2}:\d\d:\d\d|\d{4}-\d{1,2}-\d{1,2}T\d\d:\d\d:\d\d\.\d+Z))? # Timestamp
(?:(\d{6}\s+\d{1,2}:\d\d:\d\d|\d{4}-\d{1,2}-\d{1,2}T\d\d:\d\d:\d\d\.\d+(?:Z|-?\d\d:\d\d)?))? # Timestamp
\s+
(?:\s*(\d+)) # Thread ID
\s

View File

@@ -43,7 +43,7 @@ sub new {
my $genlog_line_1= qr{
\A
(?:(\d{6}\s+\d{1,2}:\d\d:\d\d|\d{4}-\d{1,2}-\d{1,2}T\d\d:\d\d:\d\d\.\d+Z))? # Timestamp
(?:(\d{6}\s+\d{1,2}:\d\d:\d\d|\d{4}-\d{1,2}-\d{1,2}T\d\d:\d\d:\d\d\.\d+(?:Z|-?\d\d:\d\d)?))? # Timestamp
\s+
(?:\s*(\d+)) # Thread ID
\s

View File

@@ -0,0 +1,36 @@
#!/usr/bin/env perl
BEGIN {
die "The PERCONA_TOOLKIT_BRANCH environment variable is not set.\n"
unless $ENV{PERCONA_TOOLKIT_BRANCH} && -d $ENV{PERCONA_TOOLKIT_BRANCH};
unshift @INC, "$ENV{PERCONA_TOOLKIT_BRANCH}/lib";
};
use strict;
use warnings FATAL => 'all';
use English qw(-no_match_vars);
use Test::More tests => 1;
use PerconaTest;
require "$trunk/bin/pt-query-digest";
my $sample = "$trunk/t/pt-query-digest/samples/pt-234-profile.log";
my @args = ( '--report-format', 'header,query_report,profile', '--type', 'genlog', $sample );
my ($output, $exit_status) = full_output(
sub { pt_query_digest::main(@args) },
stderr => 1,
);
ok(
no_diff(
sub { pt_query_digest::main(@args) },
"t/pt-query-digest/samples/pt-234.log",
),
'Parse genlog having timestamps with TZ'
);
# #############################################################################
# Done.
# #############################################################################
exit;

View File

@@ -0,0 +1,11 @@
/usr/local/mysql/bin/mysqld, Version: 5.7.19-17-log (Percona Server
(GPL), Release 17, Revision e19a6b7b73f). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
2017-12-08T14:56:57.252473-07:00 1 Query BEGIN
2017-12-08T14:56:57.252565-07:00 1 Query COMMIT /* implicit, from Xid_log_event */
2017-12-08T14:56:57.252668-07:00 31 Execute SELECT pid, nhash, version, isDir, oid, isDel, userId, grpId, UNIX_TIMESTAMP(ctime) AS ctime FROM namespace WHERE nhash = 18271836372746674803 AND pid = 1674083955 AND version = 0
2017-12-08T14:56:57.252705-07:00 349 Execute SELECT id, name, pid, flags, userid, grpid as groupid, UNIX_TIMESTAMP(ctime) as ctime, COALESCE(UNIX_TIMESTAMP(mtime), 0) as mtime FROM directory WHERE id = 1127458736
2017-12-08T14:56:57.253326-07:00 1 Query BEGIN
2017-12-08T14:56:57.253412-07:00 1 Query COMMIT /* implicit, from Xid_log_event */
2017-12-08T14:56:57.253694-07:00 1 Query BEGIN

View File

@@ -0,0 +1,98 @@
# Overall: 7 total, 4 unique, 0 QPS, 0x concurrency ______________________
# Time range: 2017-12-08T14:56:57.252473-07:00 to 2017-12-08T14:56:57.253694-07:00
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 0 0 0 0 0 0 0
# Query size 161 5 42 23 40.45 15.07 28.75
# Query 1: 0 QPS, 0x concurrency, ID 0x9617DE062D3FFA8D at byte 912 ______
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2017-12-08T14:56:57.252565-07:00 to 2017-12-08T14:56:57.253412-07:00
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 28 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 52 84 42 42 42 42 0 42
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS LIKE 'Xid_log_event'\G
# SHOW CREATE TABLE `Xid_log_event`\G
COMMIT /* implicit, from Xid_log_event */ \G
# Query 2: 0 QPS, 0x concurrency, ID 0x2342554AF88317C9 at byte 780 ______
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2017-12-08T14:56:57.252473-07:00 to 2017-12-08T14:56:57.253326-07:00
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 28 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 7 12 6 6 6 6 0 6
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
BEGIN \G
# Query 3: 0 QPS, 0x concurrency, ID 0x1228F184663C8627 at byte 566 ______
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2017-12-08T14:56:57.252668-07:00 to 2017-12-08T14:56:57.252705-07:00
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 28 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 37 60 30 30 30 30 0 30
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
administrator command: Execute\G
# Query 4: 0 QPS, 0x concurrency, ID 0x85FFF5AA78E5FF6A at byte 959 ______
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2017-12-08T14:56:57.253694-07:00
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 14 1
# Exec time 0 0 0 0 0 0 0 0
# Query size 3 5 5 5 5 5 0 5
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
BEGIN\G
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0x9617DE062D3FFA8D 0.0000 0.0% 2 0.0000 0.00 COMMIT Xid_log_event
# 2 0x2342554AF88317C9 0.0000 0.0% 2 0.0000 0.00 BEGIN
# 3 0x1228F184663C8627 0.0000 0.0% 2 0.0000 0.00 ADMIN EXECUTE
# 4 0x85FFF5AA78E5FF6A 0.0000 0.0% 1 0.0000 0.00 BEGIN