| Bug #116145 | [Warning] [MY-015116] [Server] Background histogram update on SCHEMA.TABLE: Lock | ||
|---|---|---|---|
| Submitted: | 18 Sep 12:45 | Modified: | 27 Sep 13:55 |
| Reporter: | Ozren Dabić | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: Docker Image | Severity: | S5 (Performance) |
| Version: | 9.0.1 | OS: | Any |
| Assigned to: | CPU Architecture: | x86 | |
| Tags: | histogram, import, warning | ||
[18 Sep 12:45]
Ozren Dabić
[18 Sep 12:47]
Ozren Dabić
Expected output from MySQL 8.3.0 running on Docker
Attachment: expected.log (application/octet-stream, text), 5.09 KiB.
[18 Sep 12:52]
Ozren Dabić
Changing to more appropriate category
[18 Sep 15:16]
MySQL Verification Team
Hi Ozren, This image is not maintained by us. Can you please check https://dev.mysql.com/doc/refman/8.0/en/docker-mysql-getting-started.html and use docker provided and maintained by us: docker pull container-registry.oracle.com/mysql/community-server:tag Thanks for your interest in MySQL
[18 Sep 15:28]
Ozren Dabić
Could you please take a look at the discussion linked in the issue description? I've already reported this issue to the respective image maintainers, and they instructed me to post it upstream (here). I can also try using the suggested image.
[18 Sep 15:34]
MySQL Verification Team
Hi Ozren, Please try with our image if you can and provide full logs here in the bug report.
[18 Sep 19:05]
Ozren Dabić
I tried with the official image also: ``` FROM container-registry.oracle.com/mysql/community-server:8.3.0 LABEL maintainer="Ozren Dabić (dabico@usi.ch)" WORKDIR /docker-entrypoint-initdb.d ADD "https://www.dropbox.com/scl/fi/shdjo2utu5oskc8u8n7x8/gse.sql?rlkey=yqxtnunrb1f7s1sn9lolqaj..." gse.sql RUN chmod 755 gse.sql ``` And I get the same warnings: ``` [Entrypoint] MySQL Docker Image 9.0.1-1.2.18-server [Entrypoint] Initializing database 2024-09-18T15:57:23.876104Z 0 [System] [MY-015017] [Server] MySQL Server Initialization - start. 2024-09-18T15:57:23.879024Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 9.0.1) initializing of server in progress as process 17 2024-09-18T15:57:23.945976Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started. 2024-09-18T15:57:25.697118Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended. 2024-09-18T15:57:29.509247Z 6 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option. 2024-09-18T15:57:33.791382Z 0 [System] [MY-015018] [Server] MySQL Server Initialization - end. [Entrypoint] Database initialized 2024-09-18T15:57:33.874186Z 0 [System] [MY-015015] [Server] MySQL Server - start. 2024-09-18T15:57:35.431710Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 9.0.1) starting as process 70 2024-09-18T15:57:35.508324Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started. 2024-09-18T15:57:37.131263Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended. 2024-09-18T15:57:37.882458Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed. 2024-09-18T15:57:37.882611Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel. 2024-09-18T15:57:37.947626Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: /var/run/mysqld/mysqlx.sock 2024-09-18T15:57:37.947898Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '9.0.1' socket: '/var/lib/mysql/mysql.sock' port: 0 MySQL Community Server - GPL. 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. [Entrypoint] running /docker-entrypoint-initdb.d/gse.sql 2024-09-18T15:58:11.428463Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction 2024-09-18T15:59:23.859657Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:00:26.851560Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:01:41.111051Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:02:58.333614Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:04:20.412109Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:05:36.517074Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:07:08.254414Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:08:11.265855Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_label: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:09:13.852674Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_label: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:10:14.181525Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_label: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:11:25.965583Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_label: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:12:56.854631Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_label: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:14:04.835028Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_language: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:15:05.077066Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_language: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:16:14.923321Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_metric: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:17:19.183934Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_metric: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:18:22.790438Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_metric: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:19:30.086268Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_metric: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:20:36.122849Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_metric_aggregate: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:21:36.234958Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.git_repo_topic: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:22:39.016154Z 0 [Warning] [MY-015116] [Server] Background histogram update on gse.label_statistics: Lock wait timeout exceeded; try restarting transaction 2024-09-18T16:22:52.372065Z 163 [System] [MY-013172] [Server] Received SHUTDOWN from user root. Shutting down mysqld (Version: 9.0.1). [Entrypoint] Server shut down [Entrypoint] MySQL init process done. Ready for start up. [Entrypoint] Starting MySQL 9.0.1-1.2.18-server 2024-09-18T16:22:54.546563Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 9.0.1) MySQL Community Server - GPL. 2024-09-18T16:22:54.546650Z 0 [System] [MY-015016] [Server] MySQL Server - end. 2024-09-18T16:22:54.637632Z 0 [System] [MY-015015] [Server] MySQL Server - start. 2024-09-18T16:22:57.695782Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 9.0.1) starting as process 1 2024-09-18T16:22:57.869795Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started. 2024-09-18T16:23:00.389399Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended. 2024-09-18T16:23:01.079811Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed. 2024-09-18T16:23:01.079929Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel. 2024-09-18T16:23:01.175040Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock 2024-09-18T16:23:01.175385Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '9.0.1' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server - GPL. ```
[18 Sep 19:06]
Ozren Dabić
Sorry wrong image def it was this one: ``` FROM container-registry.oracle.com/mysql/community-server:9.0.1 LABEL maintainer="Ozren Dabić (dabico@usi.ch)" WORKDIR /docker-entrypoint-initdb.d ADD "https://www.dropbox.com/scl/fi/shdjo2utu5oskc8u8n7x8/gse.sql?rlkey=yqxtnunrb1f7s1sn9lolqaj..." gse.sql RUN chmod 755 gse.sql ``` I tried with 8.3.0 also and it did not exhibit any warnings.
[18 Sep 19:08]
Ozren Dabić
Official MySQL 9.0.1 image log
Attachment: actual.log (application/octet-stream, text), 7.33 KiB.
[19 Sep 16:05]
MySQL Verification Team
Hi Ozren, Thanks for testing with our image. Before running this 1.2G test I really needed to be sure you can see it on our image too. I am not 100% sure this is a bug or just changed behavior as these are just warning and everything runs ok but I'll verify this behavior just to be sure so that our docker team can doublecheck. Also not really sure this has to do with docker at all or it is just how 9. now runs Hvala u svakom slucaju
[20 Sep 8:57]
Ozren Dabić
After trying it out for myself on my local machine, I can definitely confirm that this is new behaviour as of version 9. Although I don't have a Linux machine, I did try with `Ver 9.0.1 for macos14.4 on x86_64 (Homebrew)` and got quite similar results. I'll also attach the log for review. The way I reproduced this locally was first to start the MySQL daemon and then run: `gzcat < gse.sql.gz | mysql -u gseadmin -p gse`. The archive is the same Dropbox-hosted database dump linked in the first comment. As you've already suggested, this probably does not impact the user in any way. Looking at the data I imported, everything seems to be there. However, users might get thrown off by the random warnings. My two cents: these background histogram updates should be performed only once the database has been initialised. Although this might be annoying to do at any given time during the server's runtime, I do think that they can be turned off and then on again during server initialisation in a Docker container. For instance, these updates can be switched off by the Docker entrypoint script and then turned on once the script finishes. This is just a suggestion, though. I'm not really familiar with the MySQL code, so I'm not sure if one can control this behaviour. I nema na čemu, hvala vama :)
[20 Sep 8:59]
Ozren Dabić
Output from importing the DB dump on macOS
Attachment: mysql_9_macos.log (application/octet-stream, text), 2.63 KiB.
[20 Sep 10:20]
MySQL Verification Team
Hi, Yes, I too reproduced on macos. It is def. change in behavior. I will change the severity to "Performance" as it really is not affecting anything except the log file.
[27 Sep 11:47]
Tobias Christiani
Posted by developer: Explanation: 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".
