[Warning] [MY-015116] [Server] Background histogram update on SCHEMA.TABLE: Lock wait timeout exceeded; try restarting transaction

[dabico]

I recently upgraded the image to the latest major version and noticed some strange warnings when trying to import an existing SQL dump during initialisation. There does not appear to be anything wrong with the imported data, but the warnings indicate some type of locking issues during the import process.

Expected Behaviour (8.3.0)

2024-09-17 14:01:57+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.3.0-1.el8 started.
2024-09-17 14:01:57+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2024-09-17 14:01:57+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.3.0-1.el8 started.
2024-09-17 14:01:57+00:00 [Note] [Entrypoint]: Initializing database files
2024-09-17T14:01:57.957208Z 0 [System] [MY-015017] [Server] MySQL Server Initialization - start.
2024-09-17T14:01:57.958978Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.3.0) initializing of server in progress as process 80
2024-09-17T14:01:57.973107Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-09-17T14:01:58.273872Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2024-09-17T14:01:59.277431Z 6 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2024-09-17T14:02:02.620540Z 0 [System] [MY-015018] [Server] MySQL Server Initialization - end.
2024-09-17 14:02:02+00:00 [Note] [Entrypoint]: Database files initialized
2024-09-17 14:02:02+00:00 [Note] [Entrypoint]: Starting temporary server
2024-09-17T14:02:02.677551Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2024-09-17T14:02:02.852366Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.3.0) starting as process 130
2024-09-17T14:02:02.866951Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-09-17T14:02:02.972573Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2024-09-17T14:02:03.188216Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2024-09-17T14:02:03.188278Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2024-09-17T14:02:03.190198Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2024-09-17T14:02:03.208447Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: /var/run/mysqld/mysqlx.sock
2024-09-17T14:02:03.208521Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.3.0'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server - GPL.
2024-09-17 14:02:03+00:00 [Note] [Entrypoint]: Temporary server started.
'/var/lib/mysql/mysql.sock' -> '/var/run/mysqld/mysqld.sock'
Warning: Unable to load '/usr/share/zoneinfo/iso3166.tab' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/zone.tab' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/zone1970.tab' as time zone. Skipping it.
2024-09-17 14:02:06+00:00 [Note] [Entrypoint]: Creating database gse
2024-09-17 14:02:06+00:00 [Note] [Entrypoint]: Creating user gseadmin
2024-09-17 14:02:06+00:00 [Note] [Entrypoint]: Giving user gseadmin access to schema gse

2024-09-17 14:02:06+00:00 [Note] [Entrypoint]: /usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/gse.sql.gz


2024-09-17 14:12:48+00:00 [Note] [Entrypoint]: Stopping temporary server
2024-09-17T14:12:48.731123Z 78 [System] [MY-013172] [Server] Received SHUTDOWN from user root. Shutting down mysqld (Version: 8.3.0).
2024-09-17T14:12:50.548528Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.3.0)  MySQL Community Server - GPL.
2024-09-17T14:12:50.548588Z 0 [System] [MY-015016] [Server] MySQL Server - end.
2024-09-17 14:12:50+00:00 [Note] [Entrypoint]: Temporary server stopped

2024-09-17 14:12:50+00:00 [Note] [Entrypoint]: MySQL init process done. Ready for start up.

2024-09-17T14:12:50.758808Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2024-09-17T14:12:50.981714Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.3.0) starting as process 1
2024-09-17T14:12:50.992036Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-09-17T14:12:51.238662Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2024-09-17T14:12:51.845086Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2024-09-17T14:12:51.845136Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2024-09-17T14:12:51.847806Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2024-09-17T14:12:51.883390Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2024-09-17T14:12:51.883515Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.3.0'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.

Actual Behaviour (9.0.1)

2024-09-17 14:21:17+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 9.0.1-1.el9 started.
2024-09-17 14:21:17+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2024-09-17 14:21:17+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 9.0.1-1.el9 started.
2024-09-17 14:21:17+00:00 [Note] [Entrypoint]: Initializing database files
2024-09-17T14:21:17.628053Z 0 [System] [MY-015017] [Server] MySQL Server Initialization - start.
2024-09-17T14:21:17.630591Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 9.0.1) initializing of server in progress as process 80
2024-09-17T14:21:17.641624Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-09-17T14:21:17.963188Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2024-09-17T14:21:19.304153Z 6 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2024-09-17T14:21:21.708623Z 0 [System] [MY-015018] [Server] MySQL Server Initialization - end.
2024-09-17 14:21:21+00:00 [Note] [Entrypoint]: Database files initialized
2024-09-17 14:21:21+00:00 [Note] [Entrypoint]: Starting temporary server
2024-09-17T14:21:21.751459Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2024-09-17T14:21:21.955733Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 9.0.1) starting as process 123
2024-09-17T14:21:21.979677Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-09-17T14:21:22.352109Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2024-09-17T14:21:22.626479Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2024-09-17T14:21:22.626541Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2024-09-17T14:21:22.631827Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2024-09-17T14:21:22.655630Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: /var/run/mysqld/mysqlx.sock
2024-09-17T14:21:22.655720Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '9.0.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server - GPL.
2024-09-17 14:21:22+00:00 [Note] [Entrypoint]: Temporary server started.
'/var/lib/mysql/mysql.sock' -> '/var/run/mysqld/mysqld.sock'
Warning: Unable to load '/usr/share/zoneinfo/iso3166.tab' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/zone.tab' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/zone1970.tab' as time zone. Skipping it.
2024-09-17 14:21:25+00:00 [Note] [Entrypoint]: Creating database gse
2024-09-17 14:21:25+00:00 [Note] [Entrypoint]: Creating user gseadmin
2024-09-17 14:21:25+00:00 [Note] [Entrypoint]: Giving user gseadmin access to schema gse

2024-09-17 14:21:25+00:00 [Note] [Entrypoint]: /usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/gse.sql.gz
2024-09-17T14:21:50.726955Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:22:56.233333Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:24:02.360010Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:25:10.091374Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:26:14.395072Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_label: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:27:17.176234Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_label: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:28:30.480213Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_label: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:29:42.666378Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_language: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:30:45.057951Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_metric: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:31:46.315883Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_metric: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:32:54.917757Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_metric_aggregate: Lock wait timeout exceeded; try restarting transaction
2024-09-17T14:34:01.907706Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_topic: Lock wait timeout exceeded; try restarting transaction


2024-09-17 14:34:30+00:00 [Note] [Entrypoint]: Stopping temporary server
2024-09-17T14:34:30.782750Z 92 [System] [MY-013172] [Server] Received SHUTDOWN from user root. Shutting down mysqld (Version: 9.0.1).
2024-09-17T14:34:31.881611Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 9.0.1)  MySQL Community Server - GPL.
2024-09-17T14:34:31.881664Z 0 [System] [MY-015016] [Server] MySQL Server - end.
2024-09-17 14:34:32+00:00 [Note] [Entrypoint]: Temporary server stopped

2024-09-17 14:34:32+00:00 [Note] [Entrypoint]: MySQL init process done. Ready for start up.

2024-09-17T14:34:32.815512Z 0 [System] [MY-015015] [Server] MySQL Server - start.
2024-09-17T14:34:33.013971Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 9.0.1) starting as process 1
2024-09-17T14:34:33.022801Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-09-17T14:34:33.323313Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2024-09-17T14:34:33.813402Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2024-09-17T14:34:33.813456Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2024-09-17T14:34:33.818198Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2024-09-17T14:34:33.852595Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2024-09-17T14:34:33.852966Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '9.0.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.

[tianon]

This is strange, and maybe I don't understand what MySQL is doing with these "background histogram updates", but it seems like it's pretty harmless, right? Wouldn't it retry the background updates later? Maybe there's a way for your database dump / import to (temporarily) disable these so that they don't run during your import, or to make them an explicit part of the import somehow instead?

Either way, I think this is probably firmly in the territory of "upstream behavior changes" not something caused by / that might be fixed by changes to the Docker images we package/maintain, and thus a more specific MySQL support forum might lead to more fruitful debugging 🙈 🙇

[dabico]

This is strange, and maybe I don't understand what MySQL is doing with these "background histogram updates", but it seems like it's pretty harmless, right?

I'm inclined to think that it has something to do with the dump itself. Looking at the SQL, all table INSERT statements are preceded by a LOCK TABLES 'TABLE' WRITE. Not sure if (and how) this affects the background histogram updates.

Either way, I think this is probably firmly in the territory of "upstream behavior changes"...

Yeah you're right, I only reported this here because I don't use MySQL on my local machine. Since I only use the DB with Docker, I thought I might ask here first. Either way, I will open an issue upstream. Thanks for the help!

Edit:

I've opened an issue upstream: https://bugs.mysql.com/bug.php?id=116145

[danyal-arif]

Are there any updates on this?

[dabico]

Are there any updates on this?

Yes, please refer to the upstream report.

[tianon]

https://bugs.mysql.com/bug.php?id=116145#c547376 is particularly relevant, and I'll copy it here for posterity:

The warning is displayed because the InnoDB background statistics thread fails
to acquire the appropriate locks to check the existence of histograms (and to
update any automatically updated histograms) on the table.

The script in the bug report triggers this warning because the table is locked
for several minutes with the "LOCK TABLES table_name WRITE;" statement while
inserting a large amount of data.

The warning exists simply to inform the user that the background histogram
update did not complete, but since there are no automatically updated histograms
on the tables in question, it would be better if it was not displayed at all.
Unfortunately, with the current implementation we have to acquire certain
metadata locks in order to be able to tell whether there are any histograms on
the table, and this operations fails when the table is locked.

It is important to note that this error event is classified as a warning, and as
such it is ignorable. It only relates to a failure to (potentially) update
statistics for use by the optimizer and is perhaps less serious than the wording
in the message implies.

We write these error events to the error log but throttle them at a rate of at
most 1 per minute (as can be seen from the logs in the bug report). The
rationale behind showing these warnings is that we wish to inform the user that
histograms have failed to update so that they can take action and run e.g.
ANALYZE TABLE manually.

Possible improvements:

• We could attempt to find a way of avoiding issuing these warnings if the table
  has no automatically updated histograms.

• This type of warning (failure to acquire locks) could perhaps be downgraded to
  a note/information event.

• We could rewrite the message to something more informative for this type of
  warning. Perhaps "Background histogram update failed on schema.table: Failure
  to acquire locks (the table was likely locked by another session). To manually
  update statistics use "ANALYZE TABLE schema.table".