search

docker-library / mysql

Docker Official Image packaging for MySQL Community Server
https://dev.mysql.com/
GNU General Public License v2.0
2.46k stars 2.19k forks source link

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

Closed dabico closed 1 week ago

dabico commented 1 week ago

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 commented 1 week ago

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 :see_no_evil: :bow:

dabico commented 1 week ago

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 commented 4 hours ago

Are there any updates on this?

dabico commented 4 hours ago

Are there any updates on this?

Yes, please refer to the upstream report.