Bug #76625 mysqld --help --verbose takes 50 seconds on unloaded system
Submitted: 8 Apr 2015 22:08 Modified: 11 Jun 2015 16:44
Reporter: Stewart Smith Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Options Severity:S3 (Non-critical)
Version:5.7.7 OS:Any
Assigned to: CPU Architecture:Any

[8 Apr 2015 22:08] Stewart Smith
Description:
On a decent sized system with the following my.cnf, executing "mysqld --help --verbose" takes ~50 seconds:

[mysqld]
datadir=/dev/shm/mysql
query_cache_type=0
table_open_cache_instances=32
innodb_buffer_pool_instances=64
innodb_checksum_algorithm=none
max_connections=2048
innodb_file_per_table
innodb_log_file_size=1024M
innodb_log_files_in_group=3
innodb_file_format=barracuda
innodb_buffer_pool_size=256GB
innodb_open_files=4000
innodb_use_native_io=1
innodb_flush_method=O_DIRECT
innodb_log_buffer_size=64M
innodb_thread_concurrency=0
innodb_max_dirty_pages_pct=25
innodb_adaptive_flushing=1
innodb_read_io_threads=16
innodb_write_io_threads=16
innodb_purge_threads=1
innodb_io_capacity=1024

How to repeat:
Considering that most of the time (according to perf) is spent in malloc, it's likely the 256GB buffer pool that's slowing things down. Perhaps for the --help code path we do not need to allocate the buffer pool.

Suggested fix:
Possibly don't allocate buffer pool when just running --help.
[9 Apr 2015 5:45] Stewart Smith
FYI, my machine does have (significantly) more than 256GB of memory, so it's not swapping :)
[9 Apr 2015 7:11] Umesh Shastry
Hello Stewart Smith,

Thank you for the report.
Observed similar behavior on my test box(251.9G RAM and mostly unused).

Thanks,
Umesh
[9 Apr 2015 7:12] Umesh Shastry
// build
[umshastr@hod04]/export/umesh/server/archive: md5sum 14854415.mysql-5.7.7-rc-linux-glibc2.5-x86_64.tar
226c9aec144e7354901cd9c801acba77  14854415.mysql-5.7.7-rc-linux-glibc2.5-x86_64.tar

// Conf is in (commented out #innodb_use_native_io=1)
[umshastr@hod04]/export/umesh/server/mysql-5.7.7: ls -l ~/.my.cnf
-rw-r--r--+ 1 umshastr common 652 Apr  9 07:27 /home/umshastr/.my.cnf
[umshastr@hod04]/export/umesh/server/mysql-5.7.7: more ~/.my.cnf

[mysqld]
basedir=/export/umesh/server/mysql-5.7.7
datadir=/export/umesh/server/mysql-5.7.7/data
query_cache_type=0
table_open_cache_instances=32
innodb_buffer_pool_instances=64
innodb_checksum_algorithm=none
max_connections=2048
innodb_file_per_table
innodb_log_file_size=1024M
innodb_log_files_in_group=3
innodb_file_format=barracuda
innodb_buffer_pool_size=210GB
innodb_open_files=4000
#innodb_use_native_io=1
innodb_flush_method=O_DIRECT
innodb_log_buffer_size=64M
innodb_thread_concurrency=0
innodb_max_dirty_pages_pct=25
innodb_adaptive_flushing=1
innodb_read_io_threads=16
innodb_write_io_threads=16
innodb_purge_threads=1
innodb_io_capacity=1024

//
[umshastr@hod04]/export/umesh/server/mysql-5.7.7: time bin/mysqld --help --verbose
bin/mysqld  Ver 5.7.7-rc for linux-glibc2.5 on x86_64 (MySQL Community Server (GPL))
Copyright (c) 2000, 2015, 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.

Starts the MySQL database server.

Usage: bin/mysqld [OPTIONS]

Default options are read from the following files in the given order:
/etc/my.cnf /etc/mysql/my.cnf /usr/local/mysql/etc/my.cnf ~/.my.cnf
The following groups are read: mysqld server mysqld-5.7
..
.
To see what values a running MySQL server is using, type
'mysqladmin variables' instead of 'mysqld --verbose --help'.

real    0m52.781s
user    0m36.050s
sys     0m14.917s

// operf

CPU: Intel Ivy Bridge microarchitecture, speed 2601 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        image name               symbol name
176644   29.6458  mysqld                   sync_latch_get_pfs_key(char const*)
80561    13.5204  kallsyms                 clear_page_c_e
44863     7.5293  libc-2.17.so             __memset_sse2
35753     6.0003  libc-2.17.so             __strcmp_sse42
31106     5.2205  libc-2.17.so             malloc
29376     4.9301  kallsyms                 page_fault
23077     3.8730  libc-2.17.so             _int_malloc
21470     3.6033  kallsyms                 __mem_cgroup_commit_charge.constprop.46
16340     2.7423  libc-2.17.so             _int_free
12876     2.1610  libstdc++.so.6.0.19      /usr/lib64/libstdc++.so.6.0.19
9747      1.6358  libc-2.17.so             __strrchr_sse42
9065      1.5214  mysqld                   rw_lock_create_func(rw_lock_t*, char const*, unsigned long)
8509      1.4280  libpthread-2.17.so       pthread_cond_init@@GLIBC_2.3.2
5643      0.9471  libpthread-2.17.so       pthread_mutex_init
4974      0.8348  mysqld                   ut_new_get_key_by_file(char const*)
4716      0.7915  mysqld                   buf_chunk_init(buf_pool_t*, buf_chunk_t*, unsigned long)
4142      0.6951  libc-2.17.so             __memcpy_ssse3_back
4128      0.6928  kallsyms                 get_page_from_freelist
4106      0.6891  kallsyms                 __mem_cgroup_try_charge
3906      0.6555  kallsyms                 __rmqueue
3618      0.6072  mysqld                   ut_basename_noext(char const*, char*, unsigned long)
3426      0.5750  mysqld                   os_event::os_event(char const*)
3176      0.5330  mysqld                   ut_allocator<unsigned char>::allocate(unsigned long, unsigned char const*, char const*, bool, bool) [clone .clone.5]
[9 Apr 2015 7:12] Umesh Shastry
// with 5.6.24 release build

..

To see what values a running MySQL server is using, type
'mysqladmin variables' instead of 'mysqld --verbose --help'.
2015-04-09 09:07:50 5987 [Note] Binlog end
2015-04-09 09:07:50 5987 [Note] Shutting down plugin 'MyISAM'
2015-04-09 09:07:50 5987 [Note] Shutting down plugin 'CSV'

real    0m0.025s
user    0m0.007s
sys     0m0.009s
[umshastr@hod04]/export/umesh/server/mysql-5.6.24-linux-glibc2.5-x86_64:
[11 Jun 2015 8:42] Shaohua Wang
Posted by developer:
 
In case mysqld is run with --help --verbose option we use default buffer pool size(128M) if innodb_buffer_pool_size > 128M, but we still show the correct value for innodb_buffer_pool_size outside.
[11 Jun 2015 16:44] Paul Dubois
Noted in 5.7.8, 5.8.0 changelogs.

mysqld --help --verbose was slow if the InnoDB buffer pool was
configured to a large size. Now with those options, buffer pool
allocation is not performed.