MySQL Forums
Forum List  »  Install & Repo

In-Place Upgrade from MySQL 5.7.33 to MySQL 8.0.25 very slow
Posted by: Ralf Meyer
Date: August 11, 2021 09:00AM

Dear MySQL community,


we are currently upgrading lots of systems from MySQL 5.7.33 to the newest MySQL version (currently 8.0.25 on the MySQL APT Repo for Debian 9).

The servers on which we perform these updates contain quite a few databases (in the following case, just over 500). Therefore, we expect the update to take some time. However we have noticed that there seems to be a significant amount of time in which nothing directly related to the update is written to the logs and were wondering if some kind of issue is potentially slowing down the progress. In the following example, the upgrade took nearly 2 hours and 40 minutes. I am not sure if this is the expected timeframe for this kind of upgrade.

Please find anonymized and shortened logs in the following:

"[...]
2021-08-11T10:15:51.747433Z 1 [Note] [MY-012976] [InnoDB] 8.0.25 started; log sequence number 2391580677580
2021-08-11T10:15:52.986187Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-08-11T10:15:52.999811Z 1 [Note] [MY-011088] [Server] Data dictionary initializing version '80023'.
2021-08-11T10:15:53.551499Z 1 [Note] [MY-010337] [Server] Created Data Dictionary for upgrade
2021-08-11T10:15:56.118530Z 0 [Note] [MY-011332] [Server] Plugin mysqlx reported: 'IPv6 is available'
2021-08-11T10:15:56.119099Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. bind-address: '::' port: 33060'
2021-08-11T10:15:56.119376Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. socket: '/var/run/mysqld/mysqlx.sock''
2021-08-11T10:15:56.119641Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock

[...]

2021-08-11T10:23:45.911276Z 2 [System] [MY-011003] [Server] Finished populating Data Dictionary tables with data.
2021-08-11T10:23:46.577390Z 2 [Note] [MY-011008] [Server] Finished migrating TABLE statistics data.
2021-08-11T10:23:50.762934Z 2 [Note] [MY-011008] [Server] Finished migrating TABLE statistics data.
2021-08-11T10:23:52.371407Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 0 is 0
2021-08-11T10:23:52.372114Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 1 is 0
2021-08-11T10:23:52.372607Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 2 is 0
2021-08-11T10:23:52.373199Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 3 is 0
2021-08-11T10:23:52.373636Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 4 is 0
2021-08-11T10:23:52.374106Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 5 is 0
2021-08-11T10:23:52.374571Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 6 is 1
2021-08-11T10:23:52.988942Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 0 is 0
2021-08-11T10:23:52.989817Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 1 is 0
2021-08-11T10:23:52.990559Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 2 is 0
2021-08-11T10:23:52.991172Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 3 is 0
2021-08-11T10:23:52.991756Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 4 is 0
2021-08-11T10:23:52.992332Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 5 is 0
2021-08-11T10:23:52.992966Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 6 is 0
2021-08-11T10:23:52.993602Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 7 is 0
2021-08-11T10:23:52.994230Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 8 is 0

[...]

2021-08-11T10:23:59.233185Z 2 [Note] [MY-012100] [InnoDB] Cannot close file ./dbuser1@database1/table1.ibd, because modification count 399 != flush count 398
2021-08-11T10:23:59.238351Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 44 is 0
2021-08-11T10:23:59.243491Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 45 is 0
2021-08-11T10:23:59.248433Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 46 is 0
2021-08-11T10:23:59.253444Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 47 is 0
2021-08-11T10:23:59.258621Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 48 is 0
2021-08-11T10:23:59.263925Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 49 is 1
2021-08-11T10:23:59.298178Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 0 is 0
2021-08-11T10:23:59.307493Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 1 is 0
2021-08-11T10:23:59.314083Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 2 is 0
2021-08-11T10:23:59.320749Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 3 is 0
2021-08-11T10:23:59.326727Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 4 is 0
2021-08-11T10:23:59.332614Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 5 is 0
2021-08-11T10:23:59.338036Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 6 is 0
2021-08-11T10:23:59.343338Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 7 is 0
2021-08-11T10:23:59.348912Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 8 is 0
2021-08-11T10:23:59.354228Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 9 is 0
2021-08-11T10:24:00.003859Z 2 [Note] [MY-012100] [InnoDB] Cannot close file ./dbuser1@database1/table2.ibd, because modification count 638 != flush count 636

[...]

2021-08-11T10:24:15.602975Z 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6610ms to flush 136 and evict 0 pages

[...]

2021-08-11T10:29:01.812652Z 2 [Note] [MY-012100] [InnoDB] Cannot close file ./database2/table3.ibd, because modification count 561 != flush count 560

[...]

2021-08-11T12:43:09.021740Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 40 is 0
2021-08-11T12:43:09.340912Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 41 is 0
2021-08-11T12:43:09.627527Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 42 is 0
2021-08-11T12:43:09.924512Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 43 is 0
2021-08-11T12:43:10.224188Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 44 is 0
2021-08-11T12:43:10.528078Z 2 [Note] [MY-012102] [InnoDB] Open file list len in shard 45 is 1
2021-08-11T12:43:11.988310Z 2 [Note] [MY-010006] [Server] Using data dictionary with version '80023'.
2021-08-11T12:43:13.132423Z 5 [System] [MY-013381] [Server] Server upgrade from '50700' to '80025' started.
2021-08-11T12:43:13.700268Z 5 [Note] [MY-013386] [Server] Running queries to upgrade MySQL server.
2021-08-11T12:43:18.589135Z 5 [Note] [MY-013387] [Server] Upgrading system table data.
2021-08-11T12:43:19.378539Z 5 [Note] [MY-013385] [Server] Upgrading the sys schema.
2021-08-11T12:43:20.483500Z 5 [Note] [MY-013400] [Server] Upgrade of help tables started.
2021-08-11T12:43:20.963884Z 5 [Note] [MY-013400] [Server] Upgrade of help tables completed.
2021-08-11T12:43:21.248505Z 5 [Note] [MY-013394] [Server] Checking 'mysql' schema.
2021-08-11T12:43:21.677032Z 5 [Note] [MY-013394] [Server] Checking 'some_database' schema.
2021-08-11T12:43:22.727810Z 5 [Note] [MY-013394] [Server] Checking 'some_other_database' schema.

[...]

2021-08-11T12:53:11.812259Z 5 [Note] [MY-013394] [Server] Checking 'sys' schema.
2021-08-11T12:53:12.141931Z 5 [System] [MY-013381] [Server] Server upgrade from '50700' to '80025' completed."

As you can see, between
"2021-08-11T10:23:50.762934Z 2 [Note] [MY-011008] [Server] Finished migrating TABLE statistics data."
and
"2021-08-11T12:43:11.988310Z 2 [Note] [MY-010006] [Server] Using data dictionary with version '80023'."
there are no direct log messages related to the upgrade.

However, notices like
"2021-08-11T10:29:01.812652Z 2 [Note] [MY-012100] [InnoDB] Cannot close file ./database2/table3.ibd, because modification count 561 != flush count 560"
are logged every few seconds to minutes.

I was thinking that the progress might get stuck for some reason there, related to this message, since it is unclear what else is happening at this time. However, I am not sure, why it would suddenly continue after a few hours. I can find nothing helpful related to this message online.

If you have any idea what is going on, I would be glad to hear from you :)

Thanks and kind Regards.

Options: ReplyQuote




Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.