in slow query log administrator commands seem to inherit counters

[Aurimas Mikalauskas]

Apparently the application I'm working with is sending a ping command every so often which seems to be trashing slow query log with stats that later will break averages when aggregated. Here's few samples from slow query:

# User@Host: db[db] @ [192.168.100.33]
# Thread_id: 140286 Schema: db Last_errno: 0 Killed: 0
# Query_time: 0.007042 Lock_time: 0.000054 Rows_sent: 1 Rows_examined: 3 Rows_affected: 0 Rows_read: 0
# Bytes_sent: 688 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 9FB2839
# 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: 1 InnoDB_IO_r_bytes: 16384 InnoDB_IO_r_wait: 0.006665
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 8
SET timestamp=1299689295;
SELECT query goes here...
# User@Host: db[db] @ [192.168.100.33]
# Thread_id: 140286 Schema: db Last_errno: 0 Killed: 0
# Query_time: 0.000008 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 3 Rows_affected: 0 Rows_read: 0
# Bytes_sent: 699 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 9FB2839
# 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: 1 InnoDB_IO_r_bytes: 16384 InnoDB_IO_r_wait: 0.006665
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 8
SET timestamp=1299689295;
# administrator command: Ping;

# User@Host: db[db] @ [192.168.100.33]
# Thread_id: 138988 Schema: db Last_errno: 0 Killed: 0
# Query_time: 0.110581 Lock_time: 0.000057 Rows_sent: 1 Rows_examined: 2 Rows_affected: 0 Rows_read: 0
# Bytes_sent: 688 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 9FB05E4
# 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: 2 InnoDB_IO_r_bytes: 32768 InnoDB_IO_r_wait: 0.109936
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 9
use db;
SET timestamp=1299688570;
SELECT query
# User@Host: db[db] @ [192.168.100.33]
# Thread_id: 138988 Schema: db Last_errno: 0 Killed: 0
# Query_time: 0.000007 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 2 Rows_affected: 0 Rows_read: 0
# Bytes_sent: 699 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 9FB05E4
# 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: 2 InnoDB_IO_r_bytes: 32768 InnoDB_IO_r_wait: 0.109936
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 9
SET timestamp=1299688570;
# administrator command: Ping;

Server 5.1.55-rel12.5-log Percona Server (GPL), 12.5, Revision 200

[Stewart Smith (stewart)]

Are you saying that having Admin commands (such as ping) is the problem? Your aggregation should probably exclude these (or show them separately). Please let me know if I'm missing something.

[Stewart Smith (stewart)]

i.e. I don't think mere existence of Ping in query log is a bug, but rather a bug in producing good aggregation statistics.

I can be persuaded, but currently I don't consider this a bug.

[Aurimas Mikalauskas (aurimas-mikalauskas)]

Steward,

sure I can just skip these statements, I wrote about it here:

http://www.mysqlperformanceblog.com/2011/03/28/maatkits-mk-query-digest-filters/

And I'm not saying having admin commands is the problem, the problem is that counters seem to be showing values of a previous statement, for example:

# InnoDB_IO_r_ops: 2 InnoDB_IO_r_bytes: 32768 InnoDB_IO_r_wait: 0.109936
# InnoDB_pages_distinct: 9
...
SELECT query
# InnoDB_IO_r_ops: 2 InnoDB_IO_r_bytes: 32768 InnoDB_IO_r_wait: 0.109936
# InnoDB_pages_distinct: 9
...
# administrator command: Ping;

Why would Ping command issue 2 read operations, read 32kbytes and look at 9 distinct pages? Why would it even have InnoDB stats at all?

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-2614