[#MDEV-32544] Setting innodb_buffer_pool_size to the maximum value can cause drastic performance degradation

Comment by Marko Mäkelä [ 2023-10-23 ]

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.

Comment by Marko Mäkelä [ 2023-10-23 ]

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.

Comment by fuying [ 2023-10-23 ]

It seems that no server error log...

Comment by Sergei Golubchik [ 2023-11-20 ]

danblack, where should be an error log be when running a docker image (as in the bug description)?

Comment by Daniel Black [ 2023-11-20 ]

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).

Comment by fuying [ 2023-11-21 ]

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)

Comment by Daniel Black [ 2023-11-21 ]

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".

Comment by Daniel Black [ 2023-11-21 ]

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.

Comment by Daniel Black [ 2023-11-21 ]

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"

Comment by Marko Mäkelä [ 2023-11-22 ]

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.

[MDEV-32544] Setting innodb_buffer_pool_size to the maximum value can cause drastic performance degradation Created: 2023-10-23 Updated: 2023-11-22
Status:	Open
Project:	MariaDB Server
Component/s:	Storage Engine - InnoDB
Affects Version/s:	10.4.32, 10.5.23, 10.6.16, 10.11.5
Fix Version/s:	10.4, 10.5, 10.6, 10.11

[MDEV-32544] Setting innodb_buffer_pool_size to the maximum value can cause drastic performance degradation Created: 2023-10-23 Updated: 2023-11-22