Mariadb-docker: Version 10.2.27 takes too long to start

[JumpIfBelow]

Hi,

Thanks for providing efforts on making Docker image of MariaDB.

Since friday last week, there is an update of MariaDB which brings us to the version 10.2.27. It was breaking all of our pipelines because of the startup time being unexpectedly longer than usual.
Our script was waiting to init the database (without any SQL file, just a plain blank instance) for 30 seconds.

With the latest version, even waiting for 120 seconds isn't enough. Eventually, 180 seconds is enough, but we cannot really afford to wait 3 plain minutes juste to init the database.

I suspect there was a small change that makes it longer to start than it should.
Instead of using the image mariadb:10.2, we are actually using mariadb:10.2.26 and everything just works fine.

For example, running the following commands lead to two different time of execution:

docker run -it --rm -e MYSQL_ALLOW_EMPTY_PASSWORD=" " mariadb:10.2.26
docker run -it --rm -e MYSQL_ALLOW_EMPTY_PASSWORD=" " mariadb:10.2.27

Is there any reason that the two version are taking longer than usual?
Logs are in the end, with the working and the failing one.
it really looks like it it hiccups right after Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it., the first one waiting ~5s and the other one ~1min 10s .

Working

Initializing database


PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
To do so, start the server, then issue the following commands:

'/usr/bin/mysqladmin' -u root password 'new-password'
'/usr/bin/mysqladmin' -u root -h  password 'new-password'

Alternatively you can run:
'/usr/bin/mysql_secure_installation'

which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.

See the MariaDB Knowledgebase at http://mariadb.com/kb or the
MySQL manual for more instructions.

Please report any problems at http://mariadb.org/jira

The latest information about MariaDB is available at http://mariadb.org/.
You can find additional information about the MySQL part at:
http://dev.mysql.com
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/

Database initialized
MySQL init process in progress...
2019-09-18  8:52:57 139733439722816 [Note] mysqld (mysqld 10.2.26-MariaDB-1:10.2.26+maria~bionic) starting as process 108 ...
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Uses event mutexes
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Using Linux native AIO
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Number of pools: 1
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Using SSE2 crc32 instructions
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Completed initialization of buffer pool
2019-09-18  8:52:58 139732717434624 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread 
priority can be changed. See the man page of setpriority().
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Highest supported file format is Barracuda.
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-09-18  8:52:58 139733439722816 [Note] InnoDB: 5.7.27 started; log sequence number 1619987
2019-09-18  8:52:58 139732549867264 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool       
2019-09-18  8:52:58 139732549867264 [Note] InnoDB: Buffer pool(s) load completed at 190918  8:52:58
2019-09-18  8:52:58 139733439722816 [Note] Plugin 'FEEDBACK' is disabled.
2019-09-18  8:52:58 139733439722816 [Warning] 'user' entry 'root@c7eb1c09c8ef' ignored in --skip-name-resolve mode.2019-09-18  8:52:58 139733439722816 [Warning] 'proxies_priv' entry '@% root@c7eb1c09c8ef' ignored in --skip-name-resolve mode.
2019-09-18  8:52:58 139733439722816 [Note] Reading of all Master_info entries succeeded
2019-09-18  8:52:58 139733439722816 [Note] Added new Master_info '' to hash table
2019-09-18  8:52:58 139733439722816 [Note] mysqld: ready for connections.
Version: '10.2.26-MariaDB-1:10.2.26+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-09-18  8:53:03 139733272688384 [Warning] 'proxies_priv' entry '@% root@c7eb1c09c8ef' ignored in --skip-name-resolve mode.

2019-09-18  8:53:03 139733271660288 [Note] mysqld (initiated by: unknown): Normal shutdown
2019-09-18  8:53:03 139733271660288 [Note] Event Scheduler: Purging the queue. 0 events
2019-09-18  8:53:03 139732591830784 [Note] InnoDB: FTS optimize thread exiting.
2019-09-18  8:53:03 139733271660288 [Note] InnoDB: Starting shutdown...
2019-09-18  8:53:03 139732549867264 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2019-09-18  8:53:03 139732549867264 [Note] InnoDB: Buffer pool(s) dump completed at 190918  8:53:03
2019-09-18  8:53:04 139733271660288 [Note] InnoDB: Shutdown completed; log sequence number 1620015
2019-09-18  8:53:04 139733271660288 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-09-18  8:53:04 139733271660288 [Note] mysqld: Shutdown complete


MySQL init process done. Ready for start up.

2019-09-18  8:53:04 139813287826752 [Note] mysqld (mysqld 10.2.26-MariaDB-1:10.2.26+maria~bionic) starting as process 1 ...
2019-09-18  8:53:04 139813287826752 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-09-18  8:53:04 139813287826752 [Note] InnoDB: Uses event mutexes
2019-09-18  8:53:04 139813287826752 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-09-18  8:53:04 139813287826752 [Note] InnoDB: Using Linux native AIO
2019-09-18  8:53:04 139813287826752 [Note] InnoDB: Number of pools: 1
2019-09-18  8:53:04 139813287826752 [Note] InnoDB: Using SSE2 crc32 instructions
2019-09-18  8:53:04 139813287826752 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-09-18  8:53:05 139813287826752 [Note] InnoDB: Completed initialization of buffer pool
2019-09-18  8:53:05 139812565886720 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread 
priority can be changed. See the man page of setpriority().
2019-09-18  8:53:05 139813287826752 [Note] InnoDB: Highest supported file format is Barracuda.
2019-09-18  8:53:05 139813287826752 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-09-18  8:53:05 139813287826752 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-09-18  8:53:05 139813287826752 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-09-18  8:53:05 139813287826752 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-09-18  8:53:05 139813287826752 [Note] InnoDB: 5.7.27 started; log sequence number 1620015
2019-09-18  8:53:05 139812057118464 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool       
2019-09-18  8:53:05 139812057118464 [Note] InnoDB: Buffer pool(s) load completed at 190918  8:53:05
2019-09-18  8:53:05 139813287826752 [Note] Plugin 'FEEDBACK' is disabled.
2019-09-18  8:53:05 139813287826752 [Note] Server socket created on IP: '::'.
2019-09-18  8:53:05 139813287826752 [Warning] 'proxies_priv' entry '@% root@c7eb1c09c8ef' ignored in --skip-name-resolve mode.
2019-09-18  8:53:05 139813287826752 [Note] Reading of all Master_info entries succeeded
2019-09-18  8:53:05 139813287826752 [Note] Added new Master_info '' to hash table
2019-09-18  8:53:05 139813287826752 [Note] mysqld: ready for connections.
Version: '10.2.26-MariaDB-1:10.2.26+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

Failing

Initializing database


PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
To do so, start the server, then issue the following commands:

'/usr/bin/mysqladmin' -u root password 'new-password'
'/usr/bin/mysqladmin' -u root -h  password 'new-password'

Alternatively you can run:
'/usr/bin/mysql_secure_installation'

which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.

See the MariaDB Knowledgebase at http://mariadb.com/kb or the
MySQL manual for more instructions.

Please report any problems at http://mariadb.org/jira

The latest information about MariaDB is available at http://mariadb.org/.
You can find additional information about the MySQL part at:
http://dev.mysql.com
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/

Database initialized
MySQL init process in progress...
2019-09-18  8:47:04 139838261568832 [Note] mysqld (mysqld 10.2.27-MariaDB-1:10.2.27+maria~bionic) starting as process 109 ...
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Uses event mutexes
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Using Linux native AIO
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Number of pools: 1
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Using SSE2 crc32 instructions
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Completed initialization of buffer pool
2019-09-18  8:47:04 139837538387712 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread 
priority can be changed. See the man page of setpriority().
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Highest supported file format is Barracuda.
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: Waiting for purge to start
2019-09-18  8:47:04 139838261568832 [Note] InnoDB: 5.7.27 started; log sequence number 1619987
2019-09-18  8:47:04 139837373912832 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-09-18  8:47:04 139837373912832 [Note] InnoDB: Buffer pool(s) load completed at 190918  8:47:04
2019-09-18  8:47:04 139838261568832 [Note] Plugin 'FEEDBACK' is disabled.
2019-09-18  8:47:04 139838261568832 [Warning] 'user' entry 'root@5f42e0fb162c' ignored in --skip-name-resolve mode.2019-09-18  8:47:04 139838261568832 [Warning] 'proxies_priv' entry '@% root@5f42e0fb162c' ignored in --skip-name-resolve mode.
2019-09-18  8:47:04 139838261568832 [Note] Reading of all Master_info entries succeeded
2019-09-18  8:47:04 139838261568832 [Note] Added new Master_info '' to hash table
2019-09-18  8:47:04 139838261568832 [Note] mysqld: ready for connections.
Version: '10.2.27-MariaDB-1:10.2.27+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-09-18  8:48:13 139838100088576 [Warning] 'proxies_priv' entry '@% root@5f42e0fb162c' ignored in --skip-name-resolve mode.

2019-09-18  8:48:13 139838099781376 [Note] mysqld (initiated by: unknown): Normal shutdown
2019-09-18  8:48:13 139838099781376 [Note] Event Scheduler: Purging the queue. 0 events
2019-09-18  8:48:13 139837415876352 [Note] InnoDB: FTS optimize thread exiting.
2019-09-18  8:48:13 139838099781376 [Note] InnoDB: Starting shutdown...
2019-09-18  8:48:13 139837373912832 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2019-09-18  8:48:13 139837373912832 [Note] InnoDB: Buffer pool(s) dump completed at 190918  8:48:13
2019-09-18  8:48:14 139838099781376 [Note] InnoDB: Shutdown completed; log sequence number 17750384
2019-09-18  8:48:14 139838099781376 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-09-18  8:48:14 139838099781376 [Note] mysqld: Shutdown complete


MySQL init process done. Ready for start up.

2019-09-18  8:48:15 140237992871232 [Note] mysqld (mysqld 10.2.27-MariaDB-1:10.2.27+maria~bionic) starting as process 1 ...
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Uses event mutexes
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Using Linux native AIO
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Number of pools: 1
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Using SSE2 crc32 instructions
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Completed initialization of buffer pool
2019-09-18  8:48:15 140237270873856 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread 
priority can be changed. See the man page of setpriority().
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Highest supported file format is Barracuda.
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-09-18  8:48:15 140237992871232 [Note] InnoDB: 5.7.27 started; log sequence number 17750384
2019-09-18  8:48:15 140236898158336 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool       
2019-09-18  8:48:15 140236898158336 [Note] InnoDB: Buffer pool(s) load completed at 190918  8:48:15
2019-09-18  8:48:15 140237992871232 [Note] Plugin 'FEEDBACK' is disabled.
2019-09-18  8:48:15 140237992871232 [Note] Server socket created on IP: '::'.
2019-09-18  8:48:15 140237992871232 [Warning] 'proxies_priv' entry '@% root@5f42e0fb162c' ignored in --skip-name-resolve mode.
2019-09-18  8:48:15 140237992871232 [Note] Reading of all Master_info entries succeeded
2019-09-18  8:48:15 140237992871232 [Note] Added new Master_info '' to hash table
2019-09-18  8:48:15 140237992871232 [Note] mysqld: ready for connections.
Version: '10.2.27-MariaDB-1:10.2.27+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

[otanner]

Hi,

I noticed the same issue with mariadb:10.3.17 vs mariadb:10.3.18 (also released on Friday). I checked a little bit deeper what happens, and it looks the newer version takes a lot of disk i/o at the start. The process running inside the container then is mysql_tzinfo_to_sql and it has changed between these two Docker image versions.

The newer version of mysql_tzinfo_to_sql adds ALTER TABLEs changing timezone tables' engine type to InnoDB, then does the INSERTs, and ALTERs the tables back to MyISAM in the end. Seems like this is the reason for slow start.

# time mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql mysql
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.

real    1m16.813s
user    0m0.270s
sys     0m0.270s

# time mysql_tzinfo_to_sql /usr/share/zoneinfo | sed 's/InnoDB/MyISAM/' | mysql mysql
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.

real    0m1.612s
user    0m0.257s
sys     0m0.177s

Also starting the 10.3.18 version with -e MYSQL_INITDB_SKIP_TZINFO=1 starts the server fast (but tzinfo will be obviously missing).

[otanner]

And looks like here is the reason for that change: https://jira.mariadb.org/browse/MDEV-18778 (Fixed Versions: 10.1.42, 10.2.27, 10.3.18, 10.4.8).

[JumpIfBelow]

Hi,

Thanks for your reply. I've checked the change you are talking about, seems like it was indeed required to update this binary.

At least we know why it is happening. It is not that criticial (it still works).

I'm looking forward to see any fix, for now I'll stuck on the previous version. If there is anything to do to update to the latest version without issue, I'll do it right away and give the feedback.

[horkko]

Hi,
I'm facing the same issue with 10.4.8 even if said it is fixed in 10.4.8 from https://jira.mariadb.org/browse/MDEV-18778.
I'm trying to create an image for mariadb with SQL data inside for development.
It takes almost 10 minutes to complete! Even more if I'm building 2 images in parallel on the same server:

First build started

2019-10-25  7:29:32 0 [Note] mysqld: ready for connections.
Version: '10.4.8-MariaDB-1:10.4.8+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-10-25  7:37:31 10 [Warning] 'proxies_priv' entry '@% root@cabc89f94963' ignored in --skip-name-resolve mode.

Second build (first one still not finished)

2019-10-25 12:11:37 0 [Note] mysqld: ready for connections.
Version: '10.4.8-MariaDB-1:10.4.8+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
2019-10-25 12:11:37 0 [Note] InnoDB: Buffer pool(s) load completed at 191025 12:11:37
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-10-25 12:35:26 10 [Warning] 'proxies_priv' entry '@% root@427b38f1bef0' ignored in --skip-name-resolve mode.

I'll give a try with -e MYSQL_INITDB_SKIP_TZINFO=1 and let you know.

[sansnom]

@horkko it's not fixed in 10.4.8. It's the reverse ! The issue has been introduced by MDEV-18778. So you will be fine with a 10.4.7. ;)

[horkko]

@sansnom Thanks for pointing this out! I'll give it a try 👍

[horkko]

@sansnom Well a bit faster but still very long:

2019-10-25 13:03:30 0 [Note] mysqld: ready for connections.
Version: '10.4.7-MariaDB-1:10.4.7+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-10-25 13:06:50 10 [Warning] 'proxies_priv' entry '@% root@04777c00cb80' ignored in --skip-name-resolve mode.

[boldt]

I can confirm this issue with 10.4.7 (startup 30s) and 10.4.8 (startup 60s).

[rdlmda]

262 is related

[moschlar]

Same here...

[yosifkit]

Closing to combine to one issue in #262.