Details
-
Bug
-
Status: Open (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.4.32, 10.5.23, 10.6.16, 10.11.5
-
docker mariadb:10.11
Description
docker run --restart=always --name mariadb1011enginevalidate -e MYSQL_ROOT_PASSWORD=123456 -d mariadb:10.11
> create database test;
> use test;
> source init_tables.sql;
> source select.sql;
When executing source select.sql normally, you will get that the empty set takes about 0.002s.
But when SET GLOBAL innodb_buffer_pool_size = 9223372036854775807; this value is the legal maximum value described in the document, and the execution time of source select.sql can reach about 50 seconds.
Performance drops greatly. Why is this?
https://mariadb.com/kb/en/innodb-system-variables/#innodb_buffer_pool_size
Attachments
Issue Links
- relates to
-
MDEV-29445 reorganise innodb buffer pool (and remove buffer pool chunks)
-
- Closed
-
Activity
Were any messages written to the server error log about the buffer pool resizing? I would expect the virtual memory allocation to fail as soon as the virtual memory size of the process approaches 256 TiB.
A design constraint is that innodb_buffer_pool_size should not exceed about 80% of the available physical memory. This is not being enforced. The slowness could simply be because the system started to swap memory.
danblack, where should be an error log be when running a docker image (as in the bug description)?
The server default is stderr, so that ends up in the container log for the container retrievable with:
docker logs mariadb1011enginevalidate
|
ying you've changed your init_tables.sql file in the collations so there are invalid collations there.
$ mv ~/Downloads/init_tables.sql /tmp/d
|
$ podman run --rm --name mariadb1011enginevalidate -e MARIADB_ROOT_PASSWORD=123456 --env MARIADB_USER=test --env MARIADB_PASSWORD=test --env MARIADB_DATABASE=test -v /tmp/d:/docker-entrypoint-initdb.d:Z mariadb:10.11
|
2023-11-20 23:08:43+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.6+maria~ubu2204 started.
|
2023-11-20 23:08:43+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
|
2023-11-20 23:08:43+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.6+maria~ubu2204 started.
|
2023-11-20 23:08:43+00:00 [Note] [Entrypoint]: Initializing database files
|
2023-11-20 23:08:43 0 [Warning] mariadbd: io_uring_queue_init() failed with ENOSYS: check seccomp filters, and the kernel version (newer than 5.1 required)
|
2023-11-20 23:08:43 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
|
|
|
|
|
PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
|
To do so, start the server, then issue the following command:
|
|
|
'/usr/bin/mariadb-secure-installation'
|
|
|
which will also give you the option of removing the test
|
databases and anonymous user created by default. This is
|
strongly recommended for production servers.
|
|
|
See the MariaDB Knowledgebase at https://mariadb.com/kb
|
|
|
Please report any problems at https://mariadb.org/jira
|
|
|
The latest information about MariaDB is available at https://mariadb.org/.
|
|
|
Consider joining MariaDB's strong and vibrant community:
|
https://mariadb.org/get-involved/
|
|
|
2023-11-20 23:08:44+00:00 [Note] [Entrypoint]: Database files initialized
|
2023-11-20 23:08:44+00:00 [Note] [Entrypoint]: Starting temporary server
|
2023-11-20 23:08:44+00:00 [Note] [Entrypoint]: Waiting for server startup
|
2023-11-20 23:08:44 0 [Note] Starting MariaDB 10.11.6-MariaDB-1:10.11.6+maria~ubu2204 source revision fecd78b83785d5ae96f2c6ff340375be803cd299 as process 97
|
2023-11-20 23:08:44 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2023-11-20 23:08:44 0 [Note] InnoDB: Number of transaction pools: 1
|
2023-11-20 23:08:44 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2023-11-20 23:08:44 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
|
2023-11-20 23:08:44 0 [Warning] mariadbd: io_uring_queue_init() failed with ENOSYS: check seccomp filters, and the kernel version (newer than 5.1 required)
|
2023-11-20 23:08:44 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
|
2023-11-20 23:08:44 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
|
2023-11-20 23:08:44 0 [Note] InnoDB: Completed initialization of buffer pool
|
2023-11-20 23:08:44 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
|
2023-11-20 23:08:44 0 [Note] InnoDB: End of log at LSN=45502
|
2023-11-20 23:08:44 0 [Note] InnoDB: 128 rollback segments are active.
|
2023-11-20 23:08:44 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
|
2023-11-20 23:08:44 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
|
2023-11-20 23:08:44 0 [Note] InnoDB: log sequence number 45502; transaction id 14
|
2023-11-20 23:08:44 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2023-11-20 23:08:44 0 [Warning] 'user' entry 'root@5062efa52f76' ignored in --skip-name-resolve mode.
|
2023-11-20 23:08:44 0 [Warning] 'proxies_priv' entry '@% root@5062efa52f76' ignored in --skip-name-resolve mode.
|
2023-11-20 23:08:44 0 [Note] mariadbd: ready for connections.
|
Version: '10.11.6-MariaDB-1:10.11.6+maria~ubu2204' socket: '/run/mysqld/mysqld.sock' port: 0 mariadb.org binary distribution
|
2023-11-20 23:08:45+00:00 [Note] [Entrypoint]: Temporary server started.
|
2023-11-20 23:08:45+00:00 [Note] [Entrypoint]: Creating database test
|
2023-11-20 23:08:45+00:00 [Note] [Entrypoint]: Creating user test
|
2023-11-20 23:08:45+00:00 [Note] [Entrypoint]: Giving user test access to schema test
|
2023-11-20 23:08:45+00:00 [Note] [Entrypoint]: Securing system users (equivalent to running mysql_secure_installation)
|
|
|
2023-11-20 23:08:45+00:00 [Note] [Entrypoint]: /usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/init_tables.sql
|
ERROR 1273 (HY000) at line 1: Unknown collation: 'eucjpms_general_ci'
|
I tried the following (but the last is wrong for charset binary)
$ sed -i -e 's/eucjpms_general_ci/eucjpms_japanese_ci/g' -e 's/euckr_general_ci/euckr_korean_ci/g' -e 's/hp8_general_ci/hp8_english_ci/g' -e 's/cp932_general_ci/cp932_japanese_ci/g' -e 's/swe7_general_ci/swe7_swedish_ci/g' -e 's/binary_general_ci/latin1_general_ci/g' /tmp/d/init_tables.sql
|
In addition to what's already been said, the TLB of CPUs only support having certain amount of mapping inside the MMU of the CPU. Where more virtual space than the CPU supports has been allocated, any access to that memory, hits a memory fault, the context switch goes to the kernel and a memory mapping looking on RAM occurs. Taken to the extreme this access via RAM being so many cycles slower than MMU accessing lookups could add up to the additional time. You could look as some perf measurements on TLB counters and context switchers while doing the SELECT in both cases.
It would still be interesting to see where CPU time is spent. Can you please update the init_table.sql file to something that can be executed.
Also related to buffer chunk size, this is based on the initial innodb-buffer-pool size. The larger the pool, the larger the chunksize (for quicker resizing). This might change the execution. If you start the container with command --innodb_buffer_pool_size=9223372036854775807 (after the image name on the docker run execution).
Thank you both very much for your replies!
I am using fuzz testing technology to test MariaDB, so there may indeed be problems in the generated SQL. I used source init_tables.sql; to execute it before. Although there was an error message, it did not affect the reproduce. So this time I use mysqldump to export the database status. You should be able to create the initial database by executing backup.sql.
Here are my creation steps
1. Start a new MariaDB 10.11 container
2. CREATE DATABASE TEST;
3.USE TEST;
4. source backup.sql backup.sql
After creating the initial database state, I tested and still have this problem:
execute the statements in select.sql
>Empty set (0.003 sec)
>SET GLOBAL innodb_buffer_pool_size = 9223372036854775807;
>Query OK, 0 rows affected, 1 warning (0.000 sec)
Execute the statements in select.sql
>Empty set (52.228 sec)
Much easier thanks.
The logs from SET GLOBAL innodb_buffer_pool_size = 9223372036854775807
Version: '10.11.6-MariaDB-1:10.11.6+maria~ubu2204' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
|
2023-11-21 2:43:06 0 [Note] InnoDB: Buffer pool(s) load completed at 231121 2:43:06
|
2023-11-21 2:43:53 0 [Note] InnoDB: Resizing buffer pool from 128.000MiB to 8.000EiB (unit = 2.000MiB).
|
2023-11-21 2:43:53 0 [Note] InnoDB: Disabling adaptive hash index.
|
2023-11-21 2:43:53 0 [Note] InnoDB: Withdrawing blocks to be shrunken.
|
2023-11-21 2:43:53 0 [Note] InnoDB: Latching entire buffer pool.
|
2023-11-21 2:43:53 0 [Note] InnoDB: Resizing buffer pool from 64 chunks to 4398046511104 chunks.
|
2023-11-21 2:44:52 0 [ERROR] InnoDB: Cannot allocate 211106232533016 bytes of memory after 60 retries over 60 seconds. OS error: Cannot allocate memory (12). Check if you should increase the swap file or ulimits of your operating system. Note that on most 32-bit computers the process memory space is limited to 2 GB or 4 GB.
|
2023-11-21 2:44:52 0 [ERROR] InnoDB: failed to allocate the chunk array.
|
2023-11-21 2:44:52 0 [Note] InnoDB: Completed resizing buffer pool from 134217728 to 9223372036854775808 bytes.
|
2023-11-21 2:44:52 0 [Note] InnoDB: Resizing buffer pool failed
|
Do it again
MariaDB [(none)]> select @@innodb_buffer_pool_size;
|
+---------------------------+
|
| @@innodb_buffer_pool_size |
|
+---------------------------+
|
| 134217728 |
|
+---------------------------+
|
1 row in set (0.000 sec)
|
|
|
MariaDB [(none)]> SET GLOBAL innodb_buffer_pool_size = 9223372036854775807;
|
Query OK, 0 rows affected, 1 warning (0.000 sec)
|
|
|
MariaDB [(none)]> show warnings;
|
+---------+------+--------------------------------------------------------------------------------+
|
| Level | Code | Message |
|
+---------+------+--------------------------------------------------------------------------------+
|
| Warning | 1210 | innodb_buffer_pool_size must be at least innodb_buffer_pool_chunk_size=2097152 |
|
+---------+------+--------------------------------------------------------------------------------+
|
1 row in set (0.000 sec)
|
|
|
MariaDB [(none)]> select @@innodb_buffer_pool_size;
|
+---------------------------+
|
| @@innodb_buffer_pool_size |
|
+---------------------------+
|
| 134217728 |
|
+---------------------------+
|
1 row in set (0.000 sec)
|
and:
2023-11-21 2:47:11 0 [Note] InnoDB: Size did not change: old size = new size = 9223372036854775808
|
So the reason the query takes so long is the 60 seconds on retry in which there's buffer pool lock on the innodb buffer pool while resizing to prevent the query.
However, there's obviously a bunch of contradictory state about the the resize failing "Cannot allocate", "Completed", but "Resizing failed".
Version: '10.4.32-MariaDB-1:10.4.32+maria~ubu2004' socket: '/var/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
|
2023-11-21 2:57:21 0 [Note] InnoDB: Buffer pool(s) load completed at 231121 2:57:21
|
2023-11-21 2:57:32 8 [Note] InnoDB: (new size: -9223372036854775808 bytes)
|
2023-11-21 2:57:32 0 [Note] InnoDB: Resizing buffer pool from 268435456 to 9223372036854775808 (unit=134217728).
|
2023-11-21 2:57:32 0 [Note] InnoDB: Disabling adaptive hash index.
|
2023-11-21 2:57:32 0 [Note] InnoDB: disabled adaptive hash index.
|
2023-11-21 2:57:32 0 [Note] InnoDB: Withdrawing blocks to be shrunken.
|
2023-11-21 2:57:32 0 [Note] InnoDB: Latching whole of buffer pool.
|
2023-11-21 2:57:32 0 [Note] InnoDB: buffer pool 0 : resizing with chunks 2 to 68719476736.
|
2023-11-21 2:57:32 0 [ERROR] InnoDB: buffer pool 0 : failed to allocate the chunk array.
|
2023-11-21 2:57:32 0 [Note] InnoDB: Completed to resize buffer pool from 268435456 to 9223372036854775808.
|
2023-11-21 2:57:32 0 [Note] InnoDB: Re-enabled adaptive hash index.
|
2023-11-21 2:57:32 0 [Note] InnoDB: Resizing buffer pool failed, finished resizing at 231121 2:57:32.
|
10.4 doesn't delay on the the select as it doesn't keep trying. However the output message around "Completed to resize" needs correction..
|
10.4 |
MariaDB [(none)]> select @@innodb_buffer_pool_size;
|
+---------------------------+
|
| @@innodb_buffer_pool_size |
|
+---------------------------+
|
| 268435456 |
|
+---------------------------+
|
1 row in set (0.000 sec)
|
|
|
MariaDB [(none)]> SET GLOBAL innodb_buffer_pool_size = 9223372036854775807; show warnings ;
|
Query OK, 0 rows affected, 1 warning (0.000 sec)
|
|
|
+---------+------+--------------------------------------------------------------------------+
|
| Level | Code | Message |
|
+---------+------+--------------------------------------------------------------------------+
|
| Warning | 1292 | Truncated incorrect innodb_buffer_pool_size value: '9223372036854775807' |
|
+---------+------+--------------------------------------------------------------------------+
|
1 row in set (0.000 sec)
|
|
|
MariaDB [(none)]> select @@innodb_buffer_pool_size;
|
+---------------------------+
|
| @@innodb_buffer_pool_size |
|
+---------------------------+
|
| 268435456 |
|
+---------------------------+
|
1 row in set (0.000 sec)
|
Try behaviour starts at 10.5:
|
10.5.23-6cfd2ba397b0ca689d8ff1bdb9fc4a4dc516a5eb / 10.6.16-b83c379420a8846ae4b28768d3c81fa354cca056 |
2023-11-21 2:59:00 0 [Note] InnoDB: Buffer pool(s) load completed at 231121 2:59:00
|
2023-11-21 2:59:03 3 [Note] InnoDB: Requested to resize buffer pool. (new size: -9223372036854775808 bytes)
|
2023-11-21 2:59:03 0 [Note] InnoDB: Resizing buffer pool from 134217728 to 9223372036854775808 (unit=134217728).
|
2023-11-21 2:59:03 0 [Note] InnoDB: Disabling adaptive hash index.
|
2023-11-21 2:59:03 0 [Note] InnoDB: Withdrawing blocks to be shrunken.
|
2023-11-21 2:59:03 0 [Note] InnoDB: Latching whole of buffer pool.
|
2023-11-21 2:59:03 0 [Note] InnoDB: buffer pool resizing with chunks 1 to 68719476736.
|
2023-11-21 3:00:02 0 [ERROR] InnoDB: Cannot allocate 3298534883352 bytes of memory after 60 retries over 60 seconds. OS error: Cannot allocate memory (12). Check if you should increase the swap file or ulimits of your operating system. Note that on most 32-bit computers the process memory space is limited to 2 GB or 4 GB.
|
2023-11-21 3:00:02 0 [ERROR] InnoDB: failed to allocate the chunk array.
|
2023-11-21 3:00:02 0 [Note] InnoDB: Completed to resize buffer pool from 134217728 to 9223372036854775808.
|
2023-11-21 3:00:02 0 [Note] InnoDB: Resizing buffer pool failed, finished resizing at 231121 3:00:02.
|
|
10.5 |
MariaDB [(none)]> select @@innodb_buffer_pool_size;
|
+---------------------------+
|
| @@innodb_buffer_pool_size |
|
+---------------------------+
|
| 134217728 |
|
+---------------------------+
|
1 row in set (0.000 sec)
|
|
|
MariaDB [(none)]>
|
MariaDB [(none)]> SET GLOBAL innodb_buffer_pool_size = 9223372036854775807; show warnings ;
|
Query OK, 0 rows affected, 1 warning (0.000 sec)
|
|
|
+---------+------+--------------------------------------------------------------------------+
|
| Level | Code | Message |
|
+---------+------+--------------------------------------------------------------------------+
|
| Warning | 1292 | Truncated incorrect innodb_buffer_pool_size value: '9223372036854775807' |
|
+---------+------+--------------------------------------------------------------------------+
|
1 row in set (0.000 sec)
|
|
|
MariaDB [(none)]>
|
MariaDB [(none)]> select @@innodb_buffer_pool_size;
|
+---------------------------+
|
| @@innodb_buffer_pool_size |
|
+---------------------------+
|
| 134217728 |
|
+---------------------------+
|
1 row in set (0.000 sec)
|
|
|
(after a 1minute)
|
MariaDB [(none)]> select @@innodb_buffer_pool_size;
|
+---------------------------+
|
| @@innodb_buffer_pool_size |
|
+---------------------------+
|
| 134217728 |
|
+---------------------------+
|
1 row in set (0.000 sec)
|
so its just that 10.11 gets nicer units and avoids negative sizes on memory.
So:
10.4+:
- fix "InnoDB: Completed to resize buffer pool" (not) error message
10.5:
- Fix signed-ness of "Requested to resize buffer pool. (new size: -9223372036854775808 bytes)"
- Remove "Note that on most 32-bit computer" when not a 32 bit computer.
- 60 second retry in storage/innobase/include/ut0new.h - exclude/reduce retries for buffer pool? When throw_on_error is true?
10.11:
- Use human readable notation on "Cannot allocate 211106232533016 bytes of memory" and "Completed resizing buffer pool"
danblack, thank you, these suggestions sound reasonable to me. I agree that the ut_allocator::allocate() retry logic does not make any sense when allocating the buffer pool. If the small allocation of a buffer pool chunk fails, then the large allocation of the additional buffer pool memory is very likely to fail as well. This code would be rewritten in MDEV-29445, where I would like to move to a single contiguous range of virtual memory addresses for the buffer pool.
It would seem to me that the maximum allowed value of innodb_buffer_pool_size on 64-bit systems is too large. I believe that the virtual address size on typical AMD64 or ARMv8 implementations is only 48 bits (256 TiB). I do not know of other architectures, such as POWER, s390x or RISC-V.
I think that the buffer pool resizing will have to be refactored as part of
MDEV-29445.