Bug #77344 Slow start up due to performance_schema overhead on MySQL 5.6
Submitted: 14 Jun 2015 2:18 Modified: 16 Jun 2015 9:19
Reporter: Jaime Sicam Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:5.6.25 OS:Any
Assigned to: Marc Alff CPU Architecture:Any

[14 Jun 2015 2:18] Jaime Sicam
Description:
If you have around 500000 tables, table_definition_cache is set at high value and performance schema is enabled, it takes minutes for MySQL 5.6 to start.

With performance_schema=on and table_definition_cache=30000, it takes 3 minutes and 34 seconds to start MySQL:

150613 22:01:10 mysqld_safe Starting mysqld daemon with databases from /home/user/sandboxes/msb_5_6_25/data
2015-06-13 22:01:11 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-06-13 22:01:11 0 [Note] /home/user/binaries/5.6.25/bin/mysqld (mysqld 5.6.25) starting as process 38415 ...
2015-06-13 22:01:11 38415 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2015-06-13 22:01:11 38415 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 2000)

2015-06-13 22:01:11 38415 [Note] Plugin 'FEDERATED' is disabled.
2015-06-13 22:01:11 38415 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-06-13 22:01:11 38415 [Note] InnoDB: The InnoDB memory heap is disabled
2015-06-13 22:01:11 38415 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-06-13 22:01:11 38415 [Note] InnoDB: Memory barrier is not used
2015-06-13 22:01:11 38415 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-06-13 22:01:11 38415 [Note] InnoDB: Using Linux native AIO
2015-06-13 22:01:11 38415 [Note] InnoDB: Using CPU crc32 instructions
2015-06-13 22:01:11 38415 [Note] InnoDB: Initializing buffer pool, size = 4.0G
2015-06-13 22:01:12 38415 [Note] InnoDB: Completed initialization of buffer pool
2015-06-13 22:01:12 38415 [Note] InnoDB: Highest supported file format is Barracuda.
2015-06-13 22:04:44 38415 [Note] InnoDB: 128 rollback segment(s) are active.
2015-06-13 22:04:44 38415 [Note] InnoDB: Waiting for purge to start
2015-06-13 22:04:44 38415 [Note] InnoDB: 5.6.25 started; log sequence number 7009552236
2015-06-13 22:04:44 38415 [Note] Server hostname (bind-address): '127.0.0.1'; port: 5625
2015-06-13 22:04:44 38415 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
2015-06-13 22:04:44 38415 [Note] Server socket created on IP: '127.0.0.1'.
2015-06-13 22:04:44 38415 [Note] Event Scheduler: Loaded 0 events
2015-06-13 22:04:44 38415 [Note] /home/user/binaries/5.6.25/bin/mysqld: ready for connections.
Version: '5.6.25'  socket: '/tmp/mysql_sandbox5625.sock'  port: 5625  MySQL Community Server (GPL)

With performance_schema=off and table_definition_cache=30000, it takes 14 seconds to start MySQL:
150613 22:07:10 mysqld_safe Starting mysqld daemon with databases from /home/user/sandboxes/msb_5_6_25/data
2015-06-13 22:07:10 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-06-13 22:07:10 0 [Note] /home/user/binaries/5.6.25/bin/mysqld (mysqld 5.6.25) starting as process 25885 ...
2015-06-13 22:07:10 25885 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2015-06-13 22:07:10 25885 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 2000)

2015-06-13 22:07:10 25885 [Note] Plugin 'FEDERATED' is disabled.
2015-06-13 22:07:10 25885 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-06-13 22:07:10 25885 [Note] InnoDB: The InnoDB memory heap is disabled
2015-06-13 22:07:10 25885 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-06-13 22:07:10 25885 [Note] InnoDB: Memory barrier is not used
2015-06-13 22:07:10 25885 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-06-13 22:07:10 25885 [Note] InnoDB: Using Linux native AIO
2015-06-13 22:07:10 25885 [Note] InnoDB: Using CPU crc32 instructions
2015-06-13 22:07:10 25885 [Note] InnoDB: Initializing buffer pool, size = 4.0G
2015-06-13 22:07:11 25885 [Note] InnoDB: Completed initialization of buffer pool
2015-06-13 22:07:11 25885 [Note] InnoDB: Highest supported file format is Barracuda.
2015-06-13 22:07:24 25885 [Note] InnoDB: 128 rollback segment(s) are active.
2015-06-13 22:07:24 25885 [Note] InnoDB: Waiting for purge to start
2015-06-13 22:07:24 25885 [Note] InnoDB: 5.6.25 started; log sequence number 7009552246
2015-06-13 22:07:24 25885 [Note] Server hostname (bind-address): '127.0.0.1'; port: 5625
2015-06-13 22:07:24 25885 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
2015-06-13 22:07:24 25885 [Note] Server socket created on IP: '127.0.0.1'.
2015-06-13 22:07:24 25885 [Note] Event Scheduler: Loaded 0 events
2015-06-13 22:07:24 25885 [Note] /home/user/binaries/5.6.25/bin/mysqld: ready for connections.
Version: '5.6.25'  socket: '/tmp/mysql_sandbox5625.sock'  port: 5625  MySQL Community Server (GPL)

How to repeat:
Create 500000 tables with 10 records on each table:
sysbench --test=/usr/share/sysbench/tests/db/oltp.lua --oltp-tables-count=500000  --mysql-user=root --mysql-password=msandbox --mysql-host=127.0.0.1 --mysql-port=5625 --oltp-table-size=10 prepare

Test starting MySQL with these settings under [mysqld] section of my.cnf:

a)
performance_schema=on
table_definition_cache=30000

b)
performance_schema=off
table_definition_cache=30000
[14 Jun 2015 2:24] Jaime Sicam
Massif output with performance schema on

Attachment: massif-with-performance-schema-on.print.txt (text/plain), 304.55 KiB.

[14 Jun 2015 2:25] Jaime Sicam
Massif output with performance schema off

Attachment: massif-with-performance-schema-off.print.txt (text/plain), 447.92 KiB.

[16 Jun 2015 9:19] Umesh Shastry
Hello Jaime Sicam,

Thank you for the report and test case.

Thanks,
Umesh
[16 Jun 2015 9:19] Umesh Shastry
test results

Attachment: 77344.results (application/octet-stream, text), 4.32 KiB.

[16 Jun 2015 9:20] Umesh Shastry
5.6.25 - massif_with_ps.out

Attachment: massif_with_ps.out (application/octet-stream, text), 223.60 KiB.

[16 Jun 2015 9:20] Umesh Shastry
5.6.25 - massif_without_ps.out

Attachment: massif_without_ps.out (application/octet-stream, text), 247.66 KiB.