Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-34566

InnoDB: Crash recovery is broken due to insufficient innodb_log_file_size (but wasn't in crash recovery)

Details

    Description

      In attempting the MDEV-34480 test case on x86_64 got the following rather different error:

      10.11.9-579450c2c10b867347612efaf67bdce3c88504cd

      $ docker-compose  -f sysbench.yml up
      Creating network "examples_default" with the default driver
      Creating examples_mariadb_1 ... done
      Creating examples_sysbench_1 ... done
      Attaching to examples_mariadb_1, examples_sysbench_1
      mariadb_1   | 2024-07-11 03:44:46+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.9+maria~ubu2204 started.
      mariadb_1   | 2024-07-11 03:44:46+00:00 [Warn] [Entrypoint]: /sys/fs/cgroup///memory.pressure not writable, functionality unavailable to MariaDB
      mariadb_1   | 2024-07-11 03:44:46+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
      mariadb_1   | 2024-07-11 03:44:46+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.9+maria~ubu2204 started.
      sysbench_1  | sysbench 1.0.20 (using bundled LuaJIT 2.1.0-beta2)
      sysbench_1  | 
      mariadb_1   | 2024-07-11 03:44:47+00:00 [Note] [Entrypoint]: Initializing database files
      mariadb_1   | 2024-07-11  3:44:47 0 [Warning] mariadbd: io_uring_queue_init() failed with ENOSYS: check seccomp filters, and the kernel version (newer than 5.1 required)
      mariadb_1   | 2024-07-11  3:44:47 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
      mariadb_1   | 
      mariadb_1   | 
      mariadb_1   | PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
      mariadb_1   | To do so, start the server, then issue the following command:
      mariadb_1   | 
      mariadb_1   | '/usr/bin/mariadb-secure-installation'
      mariadb_1   | 
      mariadb_1   | which will also give you the option of removing the test
      mariadb_1   | databases and anonymous user created by default.  This is
      mariadb_1   | strongly recommended for production servers.
      mariadb_1   | 
      mariadb_1   | See the MariaDB Knowledgebase at https://mariadb.com/kb
      mariadb_1   | 
      mariadb_1   | Please report any problems at https://mariadb.org/jira
      mariadb_1   | 
      mariadb_1   | The latest information about MariaDB is available at https://mariadb.org/.
      mariadb_1   | 
      mariadb_1   | Consider joining MariaDB's strong and vibrant community:
      mariadb_1   | https://mariadb.org/get-involved/
      mariadb_1   | 
      mariadb_1   | 2024-07-11 03:44:48+00:00 [Note] [Entrypoint]: Database files initialized
      mariadb_1   | 2024-07-11 03:44:48+00:00 [Note] [Entrypoint]: Starting temporary server
      mariadb_1   | 2024-07-11 03:44:48+00:00 [Note] [Entrypoint]: Waiting for server startup
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] Starting MariaDB 10.11.9-MariaDB-ubu2204 source revision 579450c2c10b867347612efaf67bdce3c88504cd server_uid AtcIAvqttVxNAphjlIHva3JYv+M= as process 95
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: Number of transaction pools: 1
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: Using AVX512 instructions
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
      mariadb_1   | 2024-07-11  3:44:48 0 [Warning] mariadbd: io_uring_queue_init() failed with ENOSYS: check seccomp filters, and the kernel version (newer than 5.1 required)
      mariadb_1   | 2024-07-11  3:44:48 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
      sysbench_1  | Initializing worker threads...
      sysbench_1  | 
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: Initializing buffer pool, total size = 5.000GiB, chunk size = 80.000MiB
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: Completed initialization of buffer pool
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: End of log at LSN=45518
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: 128 rollback segments are active.
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] InnoDB: log sequence number 45518; transaction id 14
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] Plugin 'FEEDBACK' is disabled.
      mariadb_1   | 2024-07-11  3:44:48 0 [Warning] 'user' entry 'root@63dcb57155de' ignored in --skip-name-resolve mode.
      mariadb_1   | 2024-07-11  3:44:48 0 [Warning] 'proxies_priv' entry '@% root@63dcb57155de' ignored in --skip-name-resolve mode.
      mariadb_1   | 2024-07-11  3:44:48 0 [Note] mariadbd: ready for connections.
      mariadb_1   | Version: '10.11.9-MariaDB-ubu2204'  socket: '/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
      mariadb_1   | 2024-07-11 03:44:49+00:00 [Note] [Entrypoint]: Temporary server started.
      mariadb_1   | 2024-07-11 03:44:49+00:00 [Note] [Entrypoint]: GENERATED ROOT PASSWORD: Q_Tax=k!Vk#1KAD42./ZhAHGu|P$>1Ig
      mariadb_1   | 2024-07-11 03:44:49+00:00 [Note] [Entrypoint]: Creating database testdb
      mariadb_1   | 2024-07-11 03:44:49+00:00 [Note] [Entrypoint]: Creating user testuser
      mariadb_1   | 2024-07-11 03:44:49+00:00 [Note] [Entrypoint]: Giving user testuser access to schema testdb
      mariadb_1   | 2024-07-11 03:44:49+00:00 [Note] [Entrypoint]: Securing system users (equivalent to running mysql_secure_installation)
      mariadb_1   | 
      mariadb_1   | 2024-07-11 03:44:49+00:00 [Note] [Entrypoint]: Stopping temporary server
      mariadb_1   | 2024-07-11  3:44:49 0 [Note] mariadbd (initiated by: unknown): Normal shutdown
      mariadb_1   | 2024-07-11  3:44:49 0 [Note] InnoDB: FTS optimize thread exiting.
      mariadb_1   | 2024-07-11  3:44:49 0 [Note] InnoDB: Starting shutdown...
      mariadb_1   | 2024-07-11  3:44:49 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
      mariadb_1   | 2024-07-11  3:44:49 0 [Note] InnoDB: Buffer pool(s) dump completed at 240711  3:44:49
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Shutdown completed; log sequence number 47108; transaction id 15
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] mariadbd: Shutdown complete
      mariadb_1   | 
      mariadb_1   | 2024-07-11 03:44:50+00:00 [Note] [Entrypoint]: Temporary server stopped
      mariadb_1   | 
      mariadb_1   | 2024-07-11 03:44:50+00:00 [Note] [Entrypoint]: MariaDB init process done. Ready for start up.
      mariadb_1   | 
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] Starting MariaDB 10.11.9-MariaDB-ubu2204 source revision 579450c2c10b867347612efaf67bdce3c88504cd server_uid AtcIAvqttVxNAphjlIHva3JYv+M= as process 1
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Number of transaction pools: 1
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Using AVX512 instructions
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
      mariadb_1   | 2024-07-11  3:44:50 0 [Warning] mariadbd: io_uring_queue_init() failed with ENOSYS: check seccomp filters, and the kernel version (newer than 5.1 required)
      mariadb_1   | 2024-07-11  3:44:50 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Initializing buffer pool, total size = 5.000GiB, chunk size = 80.000MiB
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Completed initialization of buffer pool
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: End of log at LSN=47108
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: 128 rollback segments are active.
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: log sequence number 47108; transaction id 16
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] Plugin 'FEEDBACK' is disabled.
      mariadb_1   | 2024-07-11  3:44:50 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] InnoDB: Buffer pool(s) load completed at 240711  3:44:50
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] Server socket created on IP: '0.0.0.0'.
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] Server socket created on IP: '::'.
      mariadb_1   | 2024-07-11  3:44:50 0 [Note] mariadbd: ready for connections.
      mariadb_1   | Version: '10.11.9-MariaDB-ubu2204'  socket: '/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
      sysbench_1  | Creating table 'sbtest5'...
      sysbench_1  | Creating table 'sbtest18'...
      sysbench_1  | Creating table 'sbtest2'...
      sysbench_1  | Creating table 'sbtest26'...
      sysbench_1  | Creating table 'sbtest7'...
      sysbench_1  | Creating table 'sbtest15'...
      sysbench_1  | Creating table 'sbtest22'...
      sysbench_1  | Creating table 'sbtest17'...
      sysbench_1  | Creating table 'sbtest20'...
      sysbench_1  | Creating table 'sbtest29'...
      sysbench_1  | Creating table 'sbtest1'...
      sysbench_1  | Creating table 'sbtest6'...
      sysbench_1  | Creating table 'sbtest21'...
      sysbench_1  | Creating table 'sbtest23'...
      sysbench_1  | Creating table 'sbtest10'...
      sysbench_1  | Creating table 'sbtest9'...
      sysbench_1  | Creating table 'sbtest13'...
      sysbench_1  | Creating table 'sbtest3'...
      sysbench_1  | Creating table 'sbtest28'...
      sysbench_1  | Creating table 'sbtest19'...
      sysbench_1  | Creating table 'sbtest11'...
      sysbench_1  | Creating table 'sbtest12'...
      sysbench_1  | Creating table 'sbtest14'...
      sysbench_1  | Creating table 'sbtest4'...
      sysbench_1  | Creating table 'sbtest25'...
      sysbench_1  | Creating table 'sbtest16'...
      sysbench_1  | Creating table 'sbtest8'...
      sysbench_1  | Creating table 'sbtest27'...
      sysbench_1  | Creating table 'sbtest24'...
      sysbench_1  | Creating table 'sbtest30'...
      sysbench_1  | Inserting 10000000 records into 'sbtest7'
      sysbench_1  | Inserting 10000000 records into 'sbtest5'
      sysbench_1  | Inserting 10000000 records into 'sbtest1'
      sysbench_1  | Inserting 10000000 records into 'sbtest26'
      sysbench_1  | Inserting 10000000 records into 'sbtest18'
      sysbench_1  | Inserting 10000000 records into 'sbtest17'
      sysbench_1  | Inserting 10000000 records into 'sbtest20'
      sysbench_1  | Inserting 10000000 records into 'sbtest22'
      sysbench_1  | Inserting 10000000 records into 'sbtest29'
      sysbench_1  | Inserting 10000000 records into 'sbtest21'
      sysbench_1  | Inserting 10000000 records into 'sbtest6'
      sysbench_1  | Inserting 10000000 records into 'sbtest9'
      sysbench_1  | Inserting 10000000 records into 'sbtest23'
      sysbench_1  | Inserting 10000000 records into 'sbtest3'
      sysbench_1  | Inserting 10000000 records into 'sbtest10'
      sysbench_1  | Inserting 10000000 records into 'sbtest28'
      sysbench_1  | Inserting 10000000 records into 'sbtest14'
      sysbench_1  | Inserting 10000000 records into 'sbtest19'
      sysbench_1  | Inserting 10000000 records into 'sbtest11'
      sysbench_1  | Inserting 10000000 records into 'sbtest12'
      sysbench_1  | Inserting 10000000 records into 'sbtest25'
      sysbench_1  | Inserting 10000000 records into 'sbtest4'
      sysbench_1  | Inserting 10000000 records into 'sbtest8'
      sysbench_1  | Inserting 10000000 records into 'sbtest27'
      sysbench_1  | Inserting 10000000 records into 'sbtest16'
      sysbench_1  | Inserting 10000000 records into 'sbtest24'
      sysbench_1  | Inserting 10000000 records into 'sbtest13'
      sysbench_1  | Inserting 10000000 records into 'sbtest15'
      sysbench_1  | Inserting 10000000 records into 'sbtest30'
      sysbench_1  | Inserting 10000000 records into 'sbtest2'
       sysbench_1  | Creating a secondary index on 'sbtest19'...
      sysbench_1  | Creating a secondary index on 'sbtest23'...
      sysbench_1  | Creating a secondary index on 'sbtest15'...
      sysbench_1  | Creating a secondary index on 'sbtest10'...
      sysbench_1  | Creating a secondary index on 'sbtest14'...
      sysbench_1  | Creating a secondary index on 'sbtest22'...
      sysbench_1  | Creating a secondary index on 'sbtest8'...
      sysbench_1  | Creating a secondary index on 'sbtest11'...
      sysbench_1  | Creating a secondary index on 'sbtest12'...
      sysbench_1  | Creating a secondary index on 'sbtest3'...
      sysbench_1  | Creating a secondary index on 'sbtest30'...
      sysbench_1  | Creating a secondary index on 'sbtest28'...
      sysbench_1  | Creating a secondary index on 'sbtest25'...
      sysbench_1  | Creating a secondary index on 'sbtest1'...
      sysbench_1  | Creating a secondary index on 'sbtest29'...
      sysbench_1  | Creating a secondary index on 'sbtest18'...
      sysbench_1  | Creating a secondary index on 'sbtest2'...
      sysbench_1  | Creating a secondary index on 'sbtest9'...
      sysbench_1  | Creating a secondary index on 'sbtest24'...
      sysbench_1  | Creating a secondary index on 'sbtest27'...
      sysbench_1  | Creating a secondary index on 'sbtest17'...
      sysbench_1  | Creating a secondary index on 'sbtest16'...
      sysbench_1  | Creating a secondary index on 'sbtest13'...
      sysbench_1  | Creating a secondary index on 'sbtest6'...
      sysbench_1  | Creating a secondary index on 'sbtest7'...
      sysbench_1  | Creating a secondary index on 'sbtest21'...
      sysbench_1  | Creating a secondary index on 'sbtest5'...
      sysbench_1  | Creating a secondary index on 'sbtest20'...
      sysbench_1  | Creating a secondary index on 'sbtest4'...
      sysbench_1  | Creating a secondary index on 'sbtest26'...
      mariadb_1   | 2024-07-11  3:56:24 0 [ERROR] InnoDB: Crash recovery is broken due to insufficient innodb_log_file_size; last checkpoint LSN=79013366993, current LSN=79103952908.
      mariadb_1   | 2024-07-11  3:56:29 18 [Note] InnoDB: Crash recovery was broken between LSN=79103952908 and checkpoint LSN=79014152603.
      examples_sysbench_1 exited with code 0
       
      $ podman exec  examples_mariadb_1 ls -la /var/lib/mysql
      total 336492
      drwxr-xr-x. 6 mysql mysql      4096 Jul 11 03:44 .
      drwxr-xr-x. 1 root  root       4096 Jul 10 01:48 ..
      -rw-------. 1 mysql mysql       118 Jul 11 03:44 .my-healthcheck.cnf
      -rw-rw----. 1 mysql mysql  16932864 Jul 11 03:44 aria_log.00000001
      -rw-rw----. 1 mysql mysql        52 Jul 11 03:44 aria_log_control
      -rw-rw----. 1 mysql mysql    372736 Jul 11 03:57 ddl_recovery.log
      -rw-rw----. 1 mysql mysql       838 Jul 11 03:44 ib_buffer_pool
      -rw-rw----. 1 mysql mysql 100663296 Jul 11 03:57 ib_logfile0
      -rw-rw----. 1 mysql mysql 213909504 Jul 11 03:57 ibdata1
      -rw-rw----. 1 mysql mysql  12582912 Jul 11 03:45 ibtmp1
      -rw-rw----. 1 mysql mysql         0 Jul 11 03:44 multi-master.info
      drwx------. 2 mysql mysql      4096 Jul 11 03:44 mysql
      -rw-r--r--. 1 mysql mysql        15 Jul 11 03:44 mysql_upgrade_info
      drwx------. 2 mysql mysql      4096 Jul 11 03:44 performance_schema
      drwx------. 2 mysql mysql     12288 Jul 11 03:44 sys
      drwx------. 2 mysql mysql      4096 Jul 11 03:57 testdb
      

      There's no missing MariaDB logs from output.

      Attachments

        Issue Links

          Activity

            Would it help if the wording were changed from "Crash recovery is broken" to "Crash recovery will be broken"?

            The "was broken" message is something that was introduced in MDEV-29982.

            In MDEV-14462 I tried to explain why a small innodb_log_file_size can’t be safe. We could make it safer by serializing things, but that would introduce an obvious performance bottleneck that we made significant effort to remove in MDEV-27774 and MDEV-33515.

            marko Marko Mäkelä added a comment - Would it help if the wording were changed from "Crash recovery is broken" to "Crash recovery will be broken"? The "was broken" message is something that was introduced in MDEV-29982 . In MDEV-14462 I tried to explain why a small innodb_log_file_size can’t be safe. We could make it safer by serializing things, but that would introduce an obvious performance bottleneck that we made significant effort to remove in MDEV-27774 and MDEV-33515 .

            People

              danblack Daniel Black
              danblack Daniel Black
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.