Bug #81804 Memory leak or bug in P_S instrumentation for InnoDB threads
Submitted: 10 Jun 2016 12:35 Modified: 13 Jun 2016 11:50
Reporter: Sveta Smirnova (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.7.13 OS:Any
Assigned to: CPU Architecture:Any

[10 Jun 2016 12:35] Sveta Smirnova
Description:
Performance schema shows negative values of CURRENT_NUMBER_OF_BYTES_USED for internal InnoDB threads

How to repeat:
sveta@Thinkie:~/build/mysql-5.7/mysql-test$ Logging: ./mtr  --start innodb
2016-06-10T12:33:21.123320Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2016-06-10T12:33:21.123373Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
MySQL Version 5.7.13
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/sveta/build/mysql-5.7/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
worker[1] 
Started [mysqld.1 - pid: 18757, winpid: 18757]
worker[1] Using config for test innodb.innodb
worker[1] Port and socket path for server(s):
worker[1] mysqld.1  13000  /home/sveta/build/mysql-5.7/mysql-test/var/tmp/mysqld.1.sock
worker[1] Waiting for server(s) to exit...

sveta@Thinkie:~/build/mysql-5.7/mysql-test$ mysqlmtr sys
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.7.13-debug-log Source distribution

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select * from memory_by_thread_by_current_bytes;
+-----------+---------------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
| thread_id | user                            | current_count_used | current_allocated | current_avg_alloc | current_max_alloc | total_allocated |
+-----------+---------------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
|         1 | sql/main                        |              11104 | 40.37 MiB         | 3.72 KiB          | 25.19 MiB         | 66.13 MiB       |
|        23 | root@localhost                  |                554 | 1.45 MiB          | 2.67 KiB          | 805.47 KiB        | 9.33 MiB        |
|         9 | innodb/page_cleaner_thread      |                 41 | 3.20 KiB          | 80 bytes          | 3.20 KiB          | 6.41 KiB        |
|        14 | innodb/srv_master_thread        |                  1 | 80 bytes          | 80 bytes          | 80 bytes          | 9.91 KiB        |
|        19 | innodb/buf_dump_thread          |                  1 | 32 bytes          | 32 bytes          | 32 bytes          | 299.10 KiB      |
|         8 | innodb/io_write_thread          |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        11 | innodb/srv_lock_timeout_thread  |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        12 | innodb/srv_error_monitor_thread |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        13 | innodb/srv_monitor_thread       |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        15 | innodb/srv_purge_thread         |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        16 | innodb/srv_worker_thread        |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        17 | innodb/srv_worker_thread        |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        18 | innodb/srv_worker_thread        |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        20 | innodb/dict_stats_thread        |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        21 | sql/signal_handler              |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        22 | sql/compress_gtid_table         |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|         2 | sql/thread_timer_notifier       |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|         3 | innodb/io_ibuf_thread           |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|         5 | innodb/io_read_thread           |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|         6 | innodb/io_read_thread           |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|         4 | innodb/io_log_thread            |                 -2 | -160 bytes        | 80 bytes          | 0 bytes           | 0 bytes         |
|         7 | innodb/io_write_thread          |                -41 | -3280 bytes       | 80 bytes          | 0 bytes           | 40 bytes        |
+-----------+---------------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
22 rows in set (0,10 sec)

mysql> select *from performance_schema.memory_summary_by_thread_by_event_name where CURRENT_NUMBER_OF_BYTES_USED<0\G
*************************** 1. row ***************************
                   THREAD_ID: 4
                  EVENT_NAME: memory/innodb/sync0rw
                 COUNT_ALLOC: 0
                  COUNT_FREE: 2
   SUM_NUMBER_OF_BYTES_ALLOC: 0
    SUM_NUMBER_OF_BYTES_FREE: 160
              LOW_COUNT_USED: -2
          CURRENT_COUNT_USED: -2
             HIGH_COUNT_USED: 0
    LOW_NUMBER_OF_BYTES_USED: -160
CURRENT_NUMBER_OF_BYTES_USED: -160
   HIGH_NUMBER_OF_BYTES_USED: 0
*************************** 2. row ***************************
                   THREAD_ID: 7
                  EVENT_NAME: memory/innodb/sync0rw
                 COUNT_ALLOC: 0
                  COUNT_FREE: 44
   SUM_NUMBER_OF_BYTES_ALLOC: 0
    SUM_NUMBER_OF_BYTES_FREE: 3520
              LOW_COUNT_USED: -44
          CURRENT_COUNT_USED: -44
             HIGH_COUNT_USED: 0
    LOW_NUMBER_OF_BYTES_USED: -3520
CURRENT_NUMBER_OF_BYTES_USED: -3520
   HIGH_NUMBER_OF_BYTES_USED: 0
2 rows in set (0,02 sec)

Suggested fix:
Check if this is real memory leak or if bug in Performance Schema memory instrumentation, then fix =)
[10 Jun 2016 12:58] Sveta Smirnova
If run sysbench oltp test for some time situation becomes even worse:

mysql> select * from memory_by_thread_by_current_bytes;
+-----------+---------------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
| thread_id | user                            | current_count_used | current_allocated | current_avg_alloc | current_max_alloc | total_allocated |
+-----------+---------------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
|         1 | sql/main                        |              11104 | 40.37 MiB         | 3.72 KiB          | 25.19 MiB         | 66.13 MiB       |
|         9 | innodb/page_cleaner_thread      |              58511 | 4.46 MiB          | 80 bytes          | 4.46 MiB          | 22.74 MiB       |
|        23 | root@localhost                  |                564 | 1.45 MiB          | 2.63 KiB          | 805.47 KiB        | 57.98 MiB       |
|        14 | innodb/srv_master_thread        |               2687 | 209.92 KiB        | 80 bytes          | 209.92 KiB        | 115.25 MiB      |
|        20 | innodb/dict_stats_thread        |                 47 | 7.72 KiB          | 168 bytes         | 6.88 KiB          | 6.12 MiB        |
|        19 | innodb/buf_dump_thread          |                  1 | 32 bytes          | 32 bytes          | 32 bytes          | 299.10 KiB      |
|        11 | innodb/srv_lock_timeout_thread  |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        12 | innodb/srv_error_monitor_thread |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        13 | innodb/srv_monitor_thread       |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        15 | innodb/srv_purge_thread         |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        16 | innodb/srv_worker_thread        |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        17 | innodb/srv_worker_thread        |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        18 | innodb/srv_worker_thread        |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        21 | sql/signal_handler              |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|        22 | sql/compress_gtid_table         |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|         2 | sql/thread_timer_notifier       |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|         3 | innodb/io_ibuf_thread           |                  0 | 0 bytes           | 0 bytes           | 0 bytes           | 0 bytes         |
|         4 | innodb/io_log_thread            |                -95 | -7600 bytes       | 80 bytes          | 0 bytes           | 0 bytes         |
|         6 | innodb/io_read_thread           |              -1109 | -88720 bytes      | 80 bytes          | 0 bytes           | 238.06 MiB      |
|         5 | innodb/io_read_thread           |              -1502 | -120160 bytes     | 80 bytes          | 0 bytes           | 296.04 MiB      |
|         7 | innodb/io_write_thread          |             -25533 | -2042640 bytes    | 80 bytes          | 0 bytes           | 177.23 KiB      |
|         8 | innodb/io_write_thread          |             -32978 | -2638240 bytes    | 80 bytes          | 0 bytes           | 189.45 KiB      |
+-----------+---------------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
22 rows in set (0,10 sec)
[13 Jun 2016 11:50] Umesh Shastry
Hello Sveta,

Thank you for the report and feedback.

Thanks,
Umesh
[2 Jul 10:59] minlei sun
I still found it in mysql-5.7.26-log.

mysql> select * from memory_summary_by_host_by_event_name where event_name='memory/innodb/mem0mem' and host='localhost'\G
*************************** 1. row ***************************
                        HOST: localhost
                  EVENT_NAME: memory/innodb/mem0mem
                 COUNT_ALLOC: 446
                  COUNT_FREE: 574
   SUM_NUMBER_OF_BYTES_ALLOC: 530879
    SUM_NUMBER_OF_BYTES_FREE: 1022464
              LOW_COUNT_USED: -128
          CURRENT_COUNT_USED: -128
             HIGH_COUNT_USED: 38
    LOW_NUMBER_OF_BYTES_USED: -491585
CURRENT_NUMBER_OF_BYTES_USED: -491585
   HIGH_NUMBER_OF_BYTES_USED: 44639
1 row in set (0.01 sec)

mysql> select version();
+------------+
| version()  |
+------------+
| 5.7.26-log |
+------------+
1 row in set (0.00 sec)