Bug #76100 Changing performance_schema.setup_timers affects already collected data
Submitted: 2 Mar 2015 14:46 Modified: 17 Mar 2015 16:51
Reporter: Sergey Petrunya Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:5.6.22, 5.6.25 OS:Any
Assigned to: Paul DuBois CPU Architecture:Any

[2 Mar 2015 14:46] Sergey Petrunya
Description:
Changing performance_schema.setup_timers affects the data that was already collected.

The issue affects IO-wait timers and table_io_waits_summary_by_table. Maybe, it affects other tables and other kinds of timers, as well.

How to repeat:
# Start a server with default parameters.

# Do some activity on a table
create table ten(a int);
insert into ten values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9);
select * from ten;

# Check the data about IO waits in P_S
MySQL [test]> select * from performance_schema.table_io_waits_summary_by_table where OBJECT_NAME='ten'\G
*************************** 1. row ***************************
     OBJECT_TYPE: TABLE
   OBJECT_SCHEMA: test
     OBJECT_NAME: ten
      COUNT_STAR: 21
  SUM_TIMER_WAIT: 89420712982
  MIN_TIMER_WAIT: 49762412
  AVG_TIMER_WAIT: 4258128926
  MAX_TIMER_WAIT: 86582390904
...

## So far, ok. 89420712982. / 1e12=0.08 sec, looks meaningful 
## Now, let's change the timer:

MySQL [test]>   update performance_schema.setup_timers set timer_name='MICROSECOND' where name='wait';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

## And run the query again:
MySQL [test]> select * from performance_schema.table_io_waits_summary_by_table where OBJECT_NAME='ten'\G
*************************** 1. row ***************************
     OBJECT_TYPE: TABLE
   OBJECT_SCHEMA: test
     OBJECT_NAME: ten
      COUNT_STAR: 21
  SUM_TIMER_WAIT: 258441367000000
  MIN_TIMER_WAIT: 143822000000
  AVG_TIMER_WAIT: 12306731000000
  MAX_TIMER_WAIT: 250238124000000
...

## Now, we see different values.  258441367000000. / 1e12=258 seconds, we didn't wait that long.

Suggested fix:
I'm not an expert in P_S code, but

* It seems that PFS_table objects (and PFS_table_io_stat, PFS_single_stat in particular) store "ticks".

* then, reading from summary table starts with:

int table_tiws_by_table::rnd_init(bool scan)
{
  m_normalizer= time_normalizer::get(wait_timer);
  return 0;

That is, it uses current wait timer to convert to pico-seconds. It ignores the fact that ticks could have been collected using a different timer.

More, what if one changes the timer while the statistics is being collected? I suspect, we will compute a sum of data in the old units and in the new units, i.e. we will get garbage.

A possible solution could be that updates to performance_schema.setup_timers should flush relevant statistics (i.e. serve as TRUNCATE TABLE).  I am not sure about all of implications, though, this is just a guess.
[3 Mar 2015 6:47] MySQL Verification Team
Hello Sergey,

Thank you for the report and test case.

Thanks,
Umesh
[3 Mar 2015 6:48] MySQL Verification Team
### 5.6.25

[umshastr@hod03]/export/umesh/mysql-5.6.25: bin/mysql -uroot -p -S /tmp/mysql_ushastry.sock
Enter password:
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 36
Server version: 5.6.25-enterprise-commercial-advanced-debug MySQL Enterprise Server - Advanced Edition Debug (Commercial)
..
.
mysql> use test
Database changed
mysql> create table ten(a int);
Query OK, 0 rows affected (0.01 sec)

mysql> insert into ten values (0),(1),(2),(3),(4),(5),(6),(7),(8),(9);
Query OK, 10 rows affected (0.00 sec)
Records: 10  Duplicates: 0  Warnings: 0

mysql> select * from ten;
+------+
| a    |
+------+
|    0 |
|    1 |
|    2 |
|    3 |
|    4 |
|    5 |
|    6 |
|    7 |
|    8 |
|    9 |
+------+
10 rows in set (0.00 sec)

mysql> select * from performance_schema.table_io_waits_summary_by_table where OBJECT_NAME='ten'\G
*************************** 1. row ***************************
     OBJECT_TYPE: TABLE
   OBJECT_SCHEMA: test
     OBJECT_NAME: ten
      COUNT_STAR: 21
  SUM_TIMER_WAIT: 5974027044
  MIN_TIMER_WAIT: 12453904
  AVG_TIMER_WAIT: 284477368
  MAX_TIMER_WAIT: 3753185308
      COUNT_READ: 11
  SUM_TIMER_READ: 194103960
  MIN_TIMER_READ: 12453904
  AVG_TIMER_READ: 17645604
  MAX_TIMER_READ: 59311216
     COUNT_WRITE: 10
 SUM_TIMER_WRITE: 5779923084
 MIN_TIMER_WRITE: 75126408
 AVG_TIMER_WRITE: 577992154
 MAX_TIMER_WRITE: 3753185308
     COUNT_FETCH: 11
 SUM_TIMER_FETCH: 194103960
 MIN_TIMER_FETCH: 12453904
 AVG_TIMER_FETCH: 17645604
 MAX_TIMER_FETCH: 59311216
    COUNT_INSERT: 10
SUM_TIMER_INSERT: 5779923084
MIN_TIMER_INSERT: 75126408
AVG_TIMER_INSERT: 577992154
MAX_TIMER_INSERT: 3753185308
    COUNT_UPDATE: 0
SUM_TIMER_UPDATE: 0
MIN_TIMER_UPDATE: 0
AVG_TIMER_UPDATE: 0
MAX_TIMER_UPDATE: 0
    COUNT_DELETE: 0
SUM_TIMER_DELETE: 0
MIN_TIMER_DELETE: 0
AVG_TIMER_DELETE: 0
MAX_TIMER_DELETE: 0
1 row in set (0.01 sec)

mysql> update performance_schema.setup_timers set timer_name='MICROSECOND' where name='wait';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> select * from performance_schema.table_io_waits_summary_by_table where OBJECT_NAME='ten'\G
*************************** 1. row ***************************
     OBJECT_TYPE: TABLE
   OBJECT_SCHEMA: test
     OBJECT_NAME: ten
      COUNT_STAR: 21
  SUM_TIMER_WAIT: 15476754000000
  MIN_TIMER_WAIT: 32264000000
  AVG_TIMER_WAIT: 736988000000
  MAX_TIMER_WAIT: 9723278000000
      COUNT_READ: 11
  SUM_TIMER_READ: 502860000000
  MIN_TIMER_READ: 32264000000
  AVG_TIMER_READ: 45714000000
  MAX_TIMER_READ: 153656000000
     COUNT_WRITE: 10
 SUM_TIMER_WRITE: 14973894000000
 MIN_TIMER_WRITE: 194628000000
 AVG_TIMER_WRITE: 1497389000000
 MAX_TIMER_WRITE: 9723278000000
     COUNT_FETCH: 11
 SUM_TIMER_FETCH: 502860000000
 MIN_TIMER_FETCH: 32264000000
 AVG_TIMER_FETCH: 45714000000
 MAX_TIMER_FETCH: 153656000000
    COUNT_INSERT: 10
SUM_TIMER_INSERT: 14973894000000
MIN_TIMER_INSERT: 194628000000
AVG_TIMER_INSERT: 1497389000000
MAX_TIMER_INSERT: 9723278000000
    COUNT_UPDATE: 0
SUM_TIMER_UPDATE: 0
MIN_TIMER_UPDATE: 0
AVG_TIMER_UPDATE: 0
MAX_TIMER_UPDATE: 0
    COUNT_DELETE: 0
SUM_TIMER_DELETE: 0
MIN_TIMER_DELETE: 0
AVG_TIMER_DELETE: 0
MAX_TIMER_DELETE: 0
1 row in set (0.01 sec)
[3 Mar 2015 8:49] Marc ALFF
Hi Sergey,

Your observation is correct that:

1) Events started with an old timer and ended with a new timer produce incorrect values when measured, polluting statistics

2) Statistics for events already measured are stored in the old timer unit,
and never converted to the new timer unit, causing incorrect values to be displayed when setup_timer changes.

1) is a known limitation, documented here:

http://dev.mysql.com/doc/refman/5.7/en/setup-timers-table.html

"
Modifications to the setup_timers table affect monitoring immediately. Events already in progress may use the original timer for the begin time and the new timer for the end time, which may lead to unpredictable results. If you make timer changes, you may want to use TRUNCATE TABLE to reset Performance Schema statistics.
"

2) actually used to work in very early releases, which converted timer values to picoseconds when -- collecting -- the data, and is now broken in the current implementation, which convert timer values when --displaying -- the data, possibly using the wrong unit.

The change in 2) was done in 2010 for performance overhead reasons, as part of
general improvements to the aggregation tables in the performance schema.

What was missed here is to clarify the documentation, because TRUNCATE TABLE is also needed to reset statistics for events already collected, when setup_timer changes.

Changing to a documentation bug.

Thanks for the report.
[17 Mar 2015 16:51] Paul DuBois
Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly.

Updated text for
http://dev.mysql.com/doc/refman/5.7/en/setup-timers-table.html

Modifications to the setup_timers table affect monitoring
immediately. Events already measured are stored using the original
timer unit, and events in progress may use the original timer for the
begin time and the new timer for the end time. To avoid unpredictable
results if you make timer changes, use TRUNCATE TABLE to reset
Performance Schema statistics.