Slow start up due to performance_schema overhead

[markus_albe]

Customer upgraded from 5.5 to 5.6 and start up times went up 10x or more.

Testing showed that using smaller table_definition_cache (down to 1000 from 20000) improved performance, and then "perf top" shows this call graph:

- lfind
  - 54.51% lf_hash_search
      find_or_create_file(PFS_thread*, PFS_file_class*, char const*, unsigned int, bool)
      end_file_open_wait_and_bind_to_descriptor_v1
      fil_open_single_table_tablespace(bool, bool, unsigned long, unsigned long, char const*, char const*)
      dict_check_tablespaces_and_store_max_id(dict_check_t)
      innobase_start_or_create_for_mysql()
  - 45.48% lf_hash_insert
      find_or_create_file(PFS_thread*, PFS_file_class*, char const*, unsigned int, bool)
      end_file_open_wait_and_bind_to_descriptor_v1
      fil_open_single_table_tablespace(bool, bool, unsigned long, unsigned long, char const*, char const*)

So we tested disabling performance_schema and left table_definition_cache at 20k, and effectively the start up time was very close to that of 5.5

To repeat:
- setup 5.6
- create 700k tables
- edit my.cnf and set table_definition_cache=30000
- restart the instance (and measure start up time in error log)
- edit my.cnf and set "performance_schema=0"
- restart the instance (and measure start up time in error log again)
- start up times after disabling P_S should be far shorter.

○ → cat sandboxes/msb_5_6_21/my.sandbox.cnf.customer
# The MySQL Sandbox
# Copyright (C) 2006-2013 Giuseppe Maxia
# Contacts: http://datacharmer.org
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; version 2 of the License
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA

[mysql]
prompt='mysql [\h] {\u} (\d) > '
#

[client]
user = msandbox
password = msandbox
port = 6666
socket = /tmp/mysql_sandbox6666.sock

[mysqld]
user = marcos.albe
port = 6666
socket = /tmp/mysql_sandbox6666.sock
basedir = /home/marcos.albe/sandboxes/tarballs/percona/5.6.21
datadir = /home/marcos.albe/sandboxes/msb_5_6_21/data
tmpdir = /home/marcos.albe/sandboxes/msb_5_6_21/tmp
lower_case_table_names = 0
pid-file = /home/marcos.albe/sandboxes/msb_5_6_21/data/mysql_sandbox6666.pid
bind-address = 127.0.0.1
# slow-query-log = on
# slow-query-log-file=/home/marcos.albe/sandboxes/msb_5_6_21/data/msandbox-slow.log
# general-log = on
# general-log-file=/home/marcos.albe/sandboxes/msb_5_6_21/data/msandbox-general.log
#
# additional options passed through 'my_clause'
#
log-error=msandbox.err

skip-grant-tables

auto_increment_increment = 2
auto_increment_offset = 1
character_set_server = latin1
connect_timeout = 30
default-storage-engine = innodb
innodb_buffer_pool_populate = 1
innodb_stats_on_metadata = 0
innodb_old_blocks_time = 1000
innodb_file_per_table = 1
innodb_io_capacity = 200 # set to 50% of iops
innodb_flush_log_at_trx_commit = 0 # default 1
innodb_flush_method = O_DIRECT # fsync is default, but other possibilites are O_DIRECT and O_DSYNC
innodb_file_format = barracuda # necessary for compression
innodb_file_format_max = barracuda # max supported
innodb_log_buffer_size = 8M #not very important
innodb_purge_threads = 1 # almost always yes
innodb_buffer_pool_size = 6G # 80GB on 96GB machine
innodb_buffer_pool_instances = 4 # between 8 and 16 to balance pools
innodb_log_file_size = 48M # maybe should do larger with ssd (innodb_os_log_written shows how this is doing -- one hour is good) -- larger means longer crash recovery time
key_buffer_size = 512M
log-slave-updates
slow-query-log = 1
slow-query-log-file = mysqlSlow.log
log_slow_verbosity = full
log_bin = masterLog
log-warnings-suppress = 1592
long_query_time = 20
expire_logs_days = 30
max_binlog_files = 40
max_allowed_packet = 32MB
max_connect_errors = 9000000
max_connections = 2048
max_heap_table_size = 128M
max_tmp_tables = 128
myisam_sort_buffer_size = 32M
query_cache_size = 64M
read_buffer_size = 4M
relay-log = relay
replicate-wild-ignore-table = %.tmpi\_%
replicate-wild-ignore-table = %.tmpNoRepl\_%
report-host = chddb1
server-id = 227
skip-name-resolve
slave-skip-errors = all
skip-slave-start
sort_buffer_size = 8M
thread_cache = 256
tmp_table_size = 128M
wait_timeout = 1800
user = mysql
table_definition_cache = 20000
lock_wait_timeout = 600

[mysqld_safe]
flush_caches
numa_interleave
open-files-limit = 450000
core-file-size = unlimited

[Laurynas Biveinis (laurynas-biveinis)]

Upstream?

[Jericho Rivera (jericho-rivera)]

Could this be related to - http://bugs.mysql.com/bug.php?id=68413 ?

[Valerii Kravchuk (valerii-kravchuk)]

I wonder how much RAM did you have on the system where this test was performed? Check https://bugs.mysql.com/bug.php?id=69391 - table_definition_cache is one of the variables that defines the amount of memory allocated for the performance_schema, and maybe it was just swapping with high value?

Also, is it really important to have 700K tables to reproduce the notable difference in startup time with P_S set to ON vs OFF with table_definition_cache=1000 (it seems so from perf output, but just to double check)?

[Jaime Sicam (jssicam)]

In terms of start up time, I can confirm that by having 150000 tables and having these settings on PS 5.6.24:
a) Start up time is around 60 seconds
[mysqld]
table_definition_cache = 10000
performance_schema = on

b) Start up time is around 3 seconds
[mysqld]
table_definition_cache = 10000
performance_schema = 0

[Raghavendra D Prabhu (raghavendra-prabhu)]

table_definition_cache is one of the many sizing hints used by PFS.

=======
        /* Add sizing hints from the server sizing parameters. */
        pfs_param.m_hints.m_table_definition_cache= table_def_size;
        pfs_param.m_hints.m_table_open_cache= table_cache_size;
        pfs_param.m_hints.m_max_connections= max_connections;
 pfs_param.m_hints.m_open_files_limit= requested_open_files;
===========

With a large value for any of these, the server chooses a profile for PFS among small, medium or large:

https://github.com/mysql/mysql-server/blob/5.6/storage/perfschema/pfs_autosize.cc#L121
https://github.com/mysql/mysql-server/blob/5.6/storage/perfschema/pfs_autosize.cc#L175

[Laurynas Biveinis (laurynas-biveinis)]

Has this been checked and reported on the upstream?

[Valerii Kravchuk (valerii-kravchuk)]

I can not reproduce this with upstream 5.6.24, maybe I am doing something wrong:

[openxs@chief 5.6]$ bin/mysql -uroot test -e"show variables like 'table_defin%'"
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| table_definition_cache | 20000 |
+------------------------+-------+
[openxs@chief 5.6]$ bin/mysql -uroot test -e"select count(*) from information_schema.tables"
+----------+
| count(*) |
+----------+
| 120505 |
+----------+
[openxs@chief 5.6]$ bin/mysql -uroot test -e"show variables like 'performance_schema'"
+--------------------+-------+
| Variable_name | Value |
+--------------------+-------+
| performance_schema | ON |
+--------------------+-------+
[openxs@chief 5.6]$ bin/mysql -uroot test -e"show variables like 'version%'" +-------------------------+------------------------------+
| Variable_name | Value |
+-------------------------+------------------------------+
| version | 5.6.24 |
| version_comment | MySQL Community Server (GPL) |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+------------------------------+
[openxs@chief 5.6]$ tail -100 data/chief.err
...
2015-05-27 13:42:23 5229 [Note] /home/openxs/dbs/5.6/bin/mysqld: Shutdown complete

150527 13:42:23 mysqld_safe mysqld from pid file /home/openxs/dbs/5.6/data/chief.pid ended
150527 13:42:26 mysqld_safe Starting mysqld daemon with databases from /home/openxs/dbs/5.6/data
2015-05-27 13:42:27 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-05-27 13:42:27 0 [Note] /home/openxs/dbs/5.6/bin/mysqld (mysqld 5.6.24) starting as process 5333 ...
2015-05-27 13:42:27 5333 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2015-05-27 13:42:27 5333 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 2000)

2015-05-27 13:42:27 5333 [Note] Plugin 'FEDERATED' is disabled.
2015-05-27 13:42:27 5333 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-05-27 13:42:27 5333 [Note] InnoDB: The InnoDB memory heap is disabled
2015-05-27 13:42:27 5333 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-05-27 13:42:27 5333 [Note] InnoDB: Memory barrier is not used
2015-05-27 13:42:27 5333 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-05-27 13:42:27 5333 [Note] InnoDB: Using Linux native AIO
2015-05-27 13:42:27 5333 [Note] InnoDB: Not using CPU crc32 instructions
2015-05-27 13:42:27 5333 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2015-05-27 13:42:27 5333 [Note] InnoDB: Completed initialization of buffer pool
2015-05-27 13:42:27 5333 [Note] InnoDB: Highest supported file format is Barracuda.
2015-05-27 13:42:28 5333 [Note] InnoDB: 128 rollback segment(s) are active.
2015-05-27 13:42:28 5333 [Note] InnoDB: Waiting for purge to start
2015-05-27 13:42:28 5333 [Note] InnoDB: 5.6.24 started; log sequence number 68190540
2015-05-27 13:42:28 5333 [N...

[Valerii Kravchuk (valerii-kravchuk)]

This can be observed, to some extent, with just about 30000 tables on 5.6.27:

bin/mysqld_safe --no-defaults --table_definition_cache=20000 &

2015-11-18 15:22:00 7271 [Note] InnoDB: Highest supported file format is Barracuda.
2015-11-18 15:22:06 7271 [Note] InnoDB: 128 rollback segment(s) are active.

bin/mysqld_safe --no-defaults --table_definition_cache=50000 &

2015-11-18 15:22:40 7382 [Note] InnoDB: Highest supported file format is Barracuda.
2015-11-18 15:23:03 7382 [Note] InnoDB: 128 rollback segment(s) are active.

bin/mysqld_safe --no-defaults --table_definition_cache=50000 --performance_schema=OFF &

2015-11-18 15:25:20 7524 [Note] InnoDB: Highest supported file format is Barracuda.
2015-11-18 15:25:21 7524 [Note] InnoDB: 128 rollback segment(s) are active.
2015-11-18 15:25:21 7524 [Note] InnoDB: Waiting for purge to start
2015-11-18 15:25:21 7524 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.27-75.0 started; log sequence number 288249230
2015-11-18 15:25:21 7524 [Note] Server hostname (bind-address): '*'; port: 3306
2015-11-18 15:25:21 7524 [Note] IPv6 is available.
2015-11-18 15:25:21 7524 [Note] - '::' resolves to '::';
2015-11-18 15:25:21 7524 [Note] Server socket created on IP: '::'.
2015-11-18 15:25:21 7524 [Note] Event Scheduler: Loaded 0 events
2015-11-18 15:25:21 7524 [Note] /home/openxs/dbs/p5.6/bin/mysqld: ready for connections.
Version: '5.6.27-75.0' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)

So, the same stage of startup on the same hardware takes 6 seconds with P_S and table_definition_cache of 20000, 23 seconds with 50000 and one second with 50000 when performance_schema is disabled.

[Valerii Kravchuk (valerii-kravchuk)]

Upstream 5.7.9 does NOT seem to be affected in the same way, it starts fast enough:

2015-11-19T11:44:17.462034Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2015-11-19T11:44:19.136225Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2015-11-19T11:44:19.136346Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2015-11-19T11:44:19.454677Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2015-11-19T11:44:19.462071Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2015-11-19T11:44:19.462110Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2015-11-19T11:44:19.463178Z 0 [Note] InnoDB: Waiting for purge to start
2015-11-19T11:44:19.513508Z 0 [Note] InnoDB: 5.7.9 started; log sequence number 352871785
2015-11-19T11:44:19.514378Z 0 [Note] InnoDB: not started
2015-11-19T11:44:19.514467Z 0 [Note] Plugin 'FEDERATED' is disabled.
2015-11-19T11:44:19.518168Z 0 [Note] InnoDB: Loading buffer pool(s) from /home/openxs/dbs/5.7/data/ib_buffer_pool
2015-11-19T11:44:19.518421Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2015-11-19T11:44:19.518937Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2015-11-19T11:44:19.518984Z 0 [Note] IPv6 is available.
2015-11-19T11:44:19.519002Z 0 [Note] - '::' resolves to '::';
2015-11-19T11:44:19.519013Z 0 [Note] Server socket created on IP: '::'.
2015-11-19T11:44:19.519291Z 0 [Note] InnoDB: Buffer pool(s) load completed at 151119 13:44:19
2015-11-19T11:44:19.636511Z 0 [Note] Event Scheduler: Loaded 0 events
2015-11-19T11:44:19.636793Z 0 [Note] /home/openxs/dbs/5.7/bin/mysqld: ready for connections.
Version: '5.7.9' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)

The delay is less than 2 seconds for this command:

 bin/mysqld_safe --no-defaults --table_definition_cache=50000 --table_open_cache=10000 &

and I do have 50K tables:

mysql> select version(), count(*) from information_schema.tables;
+-----------+----------+
| version() | count(*) |
+-----------+----------+
| 5.7.9 | 50282 |
+-----------+----------+
1 row in set (0,52 sec)

mysql> show variables like 'table_d%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| table_definition_cache | 50000 |
+------------------------+-------+
1 row in set (0,00 sec)

...
*************************** 229. row ***************************
  Type: performance_schema
  Name: performance_schema.memory
Status: 163510080
229 rows in set (0,03 sec)

[Valerii Kravchuk (valerii-kravchuk)]

In 5.6.27 I see the following memory usage by performance schema:

| performance_schema | performance_schema.memory | 1794090344 |

This is for:

bin/mysqld_safe --no-defaults --table_definition_cache=50000 &

So, it seems memory pre-allocation is what takes time in 5.6.x and (as 5.7 defers some meory allocation) is a reason why 5.7 is not that much affected.

[Valerii Kravchuk (valerii-kravchuk)]

Surely, memory allocated depends on instrumentation used. If we disable all instruments startup is instant:

[openxs@chief p5.6]$ bin/mysqld_safe --no-defaults --table_definition_cache=50000 --performance-schema-instrument='%=OFF' &
[1] 2849

...
2015-11-20 12:30:55 2945 [Note] InnoDB: Highest supported file format is Barracuda.
2015-11-20 12:30:55 2945 [Note] InnoDB: 128 rollback segment(s) are active.
2015-11-20 12:30:55 2945 [Note] InnoDB: Waiting for purge to start
2015-11-20 12:30:55 2945 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.27-75.0 started; log sequence number 288279594
2015-11-20 12:30:55 2945 [Note] Server hostname (bind-address): '*'; port: 3306
2015-11-20 12:30:55 2945 [Note] IPv6 is available.
2015-11-20 12:30:55 2945 [Note] - '::' resolves to '::';
2015-11-20 12:30:55 2945 [Note] Server socket created on IP: '::'.
2015-11-20 12:30:55 2945 [Note] Event Scheduler: Loaded 0 events
2015-11-20 12:30:55 2945 [Note] /home/openxs/dbs/p5.6/bin/mysqld: ready for connections.
Version: '5.6.27-75.0' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)

Even though memory use is reported the same:

| performance_schema | performance_schema.memory | 1794090344 |
+--------------------+--------------------------------------------------------------+------------+
167 rows in set (0.00 sec)

Enabling instruments after startup seems to work fastert, and may work well for those that can be re-enabled after startup:

mysql> update performance_schema.setup_instruments set enabled = 'YES', timed='YES';
Query OK, 582 rows affected (3.05 sec)
Rows matched: 582 Changed: 582 Warnings: 0

So, if total memory allocation is NOT too big (it does not depend on enabled status), it seems we can start with all/most dynamic instruments disabled by default, and then enable them when needed. This will give faster startup at a cost of some delays for enabling instruments later.

[Shahriyar Rzayev (rzayev-sehriyar)]

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