MySQL Bugs: #77344: Slow start up due to performance

Bug #77344	Slow start up due to performance_schema overhead on MySQL 5.6
Submitted:	14 Jun 2015 2:18	Modified:	10 Oct 2023 13:11
Reporter:	Jaime Sicam	Email Updates:
Status:	Can't repeat	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

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

Massif output with performance schema on

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

Massif output with performance schema off

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

Hello Jaime Sicam,

Thank you for the report and test case.

Thanks,
Umesh

test results

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

5.6.25 - massif_with_ps.out

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

5.6.25 - massif_without_ps.out

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

In MySQL 5.6, the performance schema allocates a single bloc or records to store data.

With a big table_definition_cache, the performance schema will allocate a big number of table_share entries, to keep statistics about all the tables expected.

This explains the behavior seen in 5.6: huge memory allocation, which also takes time on startup.

Starting with 5.7, the performance schema no longer allocated all N records possibly needed at once during startup, but allocates records by chunks, as needed during runtime.

This issue has been fixed in 5.7 and up by internal refactoring in 5.7.

Closing as can't reproduce (in 5.7 and 8.0).