Bug #107147 Slow server upgrades with MySQL 8
Submitted: 28 Apr 2022 6:13 Modified: 8 Nov 2022 15:34
Reporter: Georgi Sotirov Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:8.0.29 OS:Linux (Slackware)
Assigned to: MySQL Verification Team CPU Architecture:x86 (x86_64)
Tags: slow, upgrade

[28 Apr 2022 6:13] Georgi Sotirov
Description:
I'm experiencing slow server upgrades with MySQL 8 (built from source), which is clearly visible in the error log. An example from this morning:

2022-04-28T05:38:28.458971Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.28)  Source distribution.
2022-04-28T05:38:30.134569Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.29) starting as process 19190
2022-04-28T05:38:30.164564Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-04-28T05:38:41.342968Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2022-04-28T05:39:07.990620Z 4 [System] [MY-013381] [Server] Server upgrade from '80028' to '80029' started.
2022-04-28T05:41:05.329609Z 4 [System] [MY-013381] [Server] Server upgrade from '80028' to '80029' completed.
2022-04-28T05:41:17.748738Z 0 [Warning] [MY-010068] [Server] CA certificate /etc/ssl/mysql/ca.pem is self signed.
2022-04-28T05:41:17.748814Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2022-04-28T05:41:19.176279Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/mysql/mysqlx.sock
2022-04-28T05:41:19.176286Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.29'  socket: '/var/mysql/mysqld.sock'  port: 3306  Source distribution.

The slowest operation (see lines 5 and 6 above) was the server upgrade from 8.0.28 to 8.0.29 taking almost 2 minutes. The whole duration of the restart was about 2:51 minutes (see SELECT TIMEDIFF('2022-04-28 05:41:19.176286', '2022-04-28 05:38:28.458971') dur), which of course breaks some applications. The server on which this is running has more than enough CPU resources, so it puzzles me what is the bottleneck with server upgrade. Restarting the server after the server upgrade takes just seconds.

What could be the reason for this slow server upgrade? Of course, let me know what other information you need, so I could provide it.

How to repeat:
1. Build MySQL from source with GCC 11.2.0 and Boost 1.77.0 library.
2. Upgrade MySQL package.
3. Restart MySQL server, so it could perform server upgrade.
[28 Apr 2022 16:57] MySQL Verification Team
Hi,

The 8.0.29 is not yet released and I cannot verify this behavior on your build so for now, this is not a bug. Also, there are some changes in the innodb so server might need to rebuild tables hence slow upgrade.

Thanks
[30 Apr 2022 17:25] Georgi Sotirov
Uh... 8.0.29 was released on April 26-th (see https://dev.mysql.com/doc/relnotes/mysql/8.0/en/news-8-0-29.html). And I had this problem with 8.0.28 as well. This may not be a bug, sure, but how could I find more about the bottleneck? Or in other words is there any way to know what exactly happens between the lines 'Server upgrade from '80028' to '80029' started.' and 'Server upgrade from '80028' to '80029' completed.' in the log?
[30 Apr 2022 17:53] MySQL Verification Team
Hi,

You are right, my mistake, colleague already notified me I was wrong, the release notes page was not updated in time (fixed).

I do not see any difference in speed .27 -> .28 to .28 -> .29.

Upgrade procedure handles a lot of things but I do not think there is a regular way to display all the steps (debug version should be but it is not the same). What takes most of the time during update is 
 - analyze and upgrade format of mysql database
 - check all tables for need to upgrade them
 - rebuild tables that need to be upgraded

if you have huge number of tables this will take time, also if some tables are big and need to be rebuilt that will also take time.

all best
[31 May 2022 10:01] Georgi Sotirov
I somehow omitted the last response...

Anyway, I can understand that "upgrade procedure handles a lot of things", but not having anything printed in the log (in a regular way) does not allow to understand more about the delay and debug the problem.

I can assure you that I do not have huge number of tables (only about 360 tables in 15 schemas) or big tables (the largest has less than a million rows and next few largest tables are less than half a million) on this instance, so the delay remains a mystery to me...
[31 May 2022 13:10] MySQL Verification Team
Hi,

> nothing in the log

Yes, this can be improved and will be improved in time. You surely noticed that mysql_upgrade is not how things work now and that whole upgrade procedure is now part of mysqld so these changes will continue to be upgraded and more verbose upgrade will happen but ATTM there are more urgent things and I am sure you know resources are not unlimited.

> not many tables and still slow

Figuring out what takes the time to upgrade is out of scope of the bugs system. If you contact MySQL Support team I am sure they can help you optimize your system and get maximum out of it. 

kind regards
[31 May 2022 13:58] Georgi Sotirov
Yes, I'm well aware that whole upgrade procedure is now part of MySQL server as I read a lot about MySQL 8 ever since it was released as GA more than 4 years ago, listened about it at conference presentations and even discussed it with some of MySQL developers. However, I'm unable to understand why the upgrade procedure takes so long on an instance that do not have so many or so large tables. I'm sure there would always be some things more urgent, but adding some more messages in the log does not seem like a tough job. I'm actually surprised that it's not envisioned already as I'm surprised that upgrade takes so long and a small instance.

Anyway, I do not understand how MySQL Support team can help me optimize my system further when neither I nor them would be able to pinpoint the source of the problem. One cannot optimize for unknown problem, or could one? Please, explain.
[31 May 2022 16:30] MySQL Verification Team
Hi,

Well, "slow on such a small instance" is not something I can reproduce. My "relevant" test instance of 100G with 100tables and 10 databases inside a rather slow VM I upgrade in matter of seconds, basically mysqld starts with upgrade almost the same as without upgrade. Also build team uses another database they test upgrades with for automated testing before the build. That one also works without a problem (and is not that small). 

What MySQL Support team can do is review your config, show you how to attach to mysqld and trace the issue etc etc.. Lot of things that are unrelated to MySQL Bugs system. You can try getting help on https://forums.mysql.com/ (we often hang there and try to help ppl that cannot convince their mgms to get them valid subscription)
[2 Jun 2022 10:56] Georgi Sotirov
Exactly. I'm not saying there is a general problem with MySQL, but apparently there is such a problem with my instance for unknown reason. The question is: How to find out what exactly? At present I do not have a way to understand the reason.

Are you suggesting I give access to MySQL Support to my instance and my data? Sorry, I'm just and individual using MySQL, so I cannot afford subscription...
[2 Jun 2022 15:52] MySQL Verification Team
Hi,

Step1 should be IMHO posting the question on https://forums.mysql.com/

all best
[2 Jun 2022 18:29] Georgi Sotirov
Please, just close this thread.
[3 Jun 2022 4:16] MySQL Verification Team
Start with --log-error-verbosity=3 and you'll see a few more outputs between these lines:

2022-04-28T05:39:07.990620Z 4 [System] [MY-013381] [Server] Server upgrade from '80028' to '80029' started.
2022-04-28T05:41:05.329609Z 4 [System] [MY-013381] [Server] Server upgrade from '80028' to '80029' completed.

Namely:
[Note] [MY-013387] [Server] Upgrading system table data.
[Note] [MY-013385] [Server] Upgrading the sys schema.
[Note] [MY-013400] [Server] Upgrade of help tables started.
[Note] [MY-013400] [Server] Upgrade of help tables completed.
[Note] [MY-013394] [Server] Checking 'mysql' schema.
[Note] [MY-013394] [Server] Checking 'sys' schema.

Knowing one took long will be helpful.  Some of them involve quite a few DML, but they should be in a single transaction so I'd not imagine it's much overhead.  Since you got the source code:
  There are four SQL scripts executed:
  1. mysql_system_tables.sql - Creates the system tables
  2. mysql_system_tables_fix.sql - Updates the system table
  3. mysql_system_tables_data_fix.sql - Fills the system tables with meta data
  4. mysql_sys_schema.sql - Create and/or updates the sys schema

https://github.com/mysql/mysql-server/tree/8.0/scripts
[6 Oct 2022 15:31] Georgi Sotirov
Thanks for the new suggestion. I'm not sure why I'm not getting notifications for your responses, so I'm seeing your comment from June 3-rd just now. Anyway, previously I tried to "trace the issue" with strace as this was suggested on May 31-th, but the output is hundreds of thousands of lines (including many clock_nanosleep, futex, etc. system calls) with nothing of particular interest showing the reason for slow upgrade.

The problem is reproducible after each upgrade, so I'll try with your last suggestion (i.e. --log-error-verbosity=3) when new MySQL 8 release comes out later this month.
[8 Nov 2022 15:34] Georgi Sotirov
So I was finally able to run upgrade from 8.0.30 to 8.0.31 with --log-error-verbosity=3 as you suggested. Here is the additional information from the log:

2022-11-08T15:10:08.650577Z 4 [System] [MY-013381] [Server] Server upgrade from '80030' to '80031' started.
2022-11-08T15:10:08.651137Z 4 [Note] [MY-013386] [Server] Running queries to upgrade MySQL server.
2022-11-08T15:11:37.588648Z 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4046ms to flush 317 and evict 0 pages
2022-11-08T15:11:57.035231Z 4 [Note] [MY-013387] [Server] Upgrading system table data.
2022-11-08T15:12:00.616544Z 4 [Note] [MY-013385] [Server] Upgrading the sys schema.
2022-11-08T15:12:20.949557Z 4 [Note] [MY-013400] [Server] Upgrade of help tables started.
2022-11-08T15:12:22.696435Z 4 [Note] [MY-013400] [Server] Upgrade of help tables completed.
2022-11-08T15:12:22.696618Z 4 [Note] [MY-013394] [Server] Checking 'mysql' schema.
2022-11-08T15:12:25.631964Z 4 [Note] [MY-013394] [Server] Checking 'sys' schema.
2022-11-08T15:12:25.683049Z 4 [System] [MY-013381] [Server] Server upgrade from '80030' to '80031' completed.

The slowest operation appears to be "Running queries to upgrade MySQL server.", which took about 90 seconds, but "Upgrading the sys schema." took another 20 seconds. I'm not quite sure for the difference between "Page cleaner..." and "Upgrading system table data.". Can we make something out of this information?