2

MariaDB Version: '10.5.13-9

I am facing multiple unsuccessful data migration(Copy) attempts from my old legacy data environment to my DBaaS Container Environment. Performing this data migration using mysqldump with pipe to restore in my Container which is running in rootless podman with pid 1. MariaDB states, this issue is sorted with version 10.5.13-9. They cannot reproduce this bug. Not able to find the reason behind why InnoDB keep logging [Note] InnoDB: Cannot close file because of 1 pending operations.

Enabled the coredump to analyze the bug, my error logs writes: Writing a core file... Working directory at /var/lib/mysql but I cant find the core file. Not able to find the reason behind it.

I even tried creating the container with podman using below parameters. But no luck. --ulimit core=-1 --privileged
--security-opt seccomp=unconfined \

MariaDB [(none)]> show global status like "%pending%"; +------------------------------+-------+ | Variable_name | Value | +------------------------------+-------+ | Innodb_data_pending_fsyncs | 0 | | Innodb_data_pending_reads | 0 | | Innodb_data_pending_writes | 0 | | Innodb_os_log_pending_fsyncs | 0 | | Innodb_os_log_pending_writes | 0 | +------------------------------+-------+ 5 rows in set (0.001 sec)

    MariaDB [(none)]>

Error Log:

2022-01-25 11:19:05 0 [Note] mysqld: ready for connections. Version: '10.5.13-9-MariaDB-enterprise-log' socket: '/var/run/mysqld/mysqld.sock' port: 53805 MariaDB Enterprise Server 2022-01-25 11:27:26 14 [Note] Start binlog_dump to slave_server(52396), pos(mysqld-bin.000001, 369), using_gtid(0), gtid('') 2022-01-25 11:38:06 15 [Note] InnoDB: Cannot close file ./pptdatabase/fallback_stf_stat_availability_sweeper_valuecritanytype#P#p736783.ibd because of 1 pending operations . . . .

. 2022-01-25 14:11:30 15 [Note] InnoDB: Cannot close file ./pptdatabase/stf_stat_availability_externalcall_avl_hist#P#p738548.ibd because of 1 pending operations 220125 14:11:32 [ERROR] mysqld got signal 11 ; This could be because you hit a bug. It is also possible that this binary or one of the libraries it was linked against is corrupt, improperly built, or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help diagnose the problem, but since we have already crashed, something is wrong and this may fail.

Server version: 10.5.13-9-MariaDB-enterprise-log key_buffer_size=134217728 read_buffer_size=2097152 max_used_connections=13 max_threads=1502 thread_count=13 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 9397787 K bytes of memory Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x0 thread_stack 0x49000 addr2line: 'mysqld': No such file mysqld(my_print_stacktrace+0x2e)[0x563b87eb047e] Printing to addr2line failed mysqld(handle_fatal_signal+0x485)[0x563b8792b425] sigaction.c:0(__restore_rt)[0x7f943ec57b20] addr2line: 'mysqld': No such file mysqld(+0xdfc944)[0x563b87dc9944] mysqld(+0xdfd881)[0x563b87dca881] mysqld(+0x652bdd)[0x563b8761fbdd] mysqld(+0xe1086a)[0x563b87ddd86a] pthread_create.c:0(start_thread)[0x7f943ec4d14a] :0(__GI___clone)[0x7f943e061dc3] The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains information that should help you find out what is causing the crash. Writing a core file... Working directory at /var/lib/mysql Resource Limits:

Another Attempt after increasing buffer pool, log file size & log buffer also re producing same. Inndob keep logging this note messages. default_storage_engine = InnoDB innodb_buffer_pool_size = 15G innodb_log_file_size = 10G innodb_log_buffer_size = 10G innodb_file_per_table = 1 innodb_open_files = 800 innodb_io_capacity = 15000 innodb_read_io_threads = 10 innodb_write_io_threads = 20 innodb_flush_method = O_DIRECT # can be fsync O_DSYNC O_DIRECT innodb_flush_log_at_trx_commit = 1

Error Log:

Version: '10.5.13-9-MariaDB-enterprise-log' socket: '/var/run/mysqld/mysqld.sock' port: 53805 MariaDB Enterprise Server 2022-01-26 0:06:27 14 [Note] Start binlog_dump to slave_server(52396), pos(mysqld-bin.000001, 369), using_gtid(0), gtid('') 2022-01-26 0:17:58 16 [Note] InnoDB: Cannot close file . .

./pptdatabase/stf_stat_availability_officeoffice_bench_aws_mhist.ibd because of 1 pending operations

Improve this question

2 Answers 2

Reset to default
4

The signal 11 (SIGSEGV) looks like a bug. Can you please file it in the MariaDB bug tracker, against the 10.5.13 release, with as many details as possible? If possible, try to produce a resolved stack trace of the crash by attaching a debugger to the server before it crashes, or by enabling core dumps and invoking the debugger on the core dump.

We have not seen any crash like that in our internal testing, but then again, we typically run stress tests with small amounts of data, and on RAM disk.

The scenario resembles that of MDEV-25215 and that originally reported bug (excessive logging of "Cannot close", several times per second) was fixed.

The scenario is that some files need to be closed so that the maximum number of open files is not being exceeded. We are not allowed to close a file handle on which writes or fdatasync() is pending. I think that at the same time, a log checkpoint must be in progress. A larger innodb_log_file_size should make log checkpoints less frequent.

Improve this answer
2
  • Tried even with innodb log file with 10G and log buffer with 5G. No luck. Bug keep impacting mysld and getting crashed. Not able to get core dump, looks like my container going to improper state before core file writing to data directory. Though I see mysqld error log writing core file, but there is no core file present. Need to try without binary logs
    – Gopinath Karangula
    Commented Jan 26, 2022 at 14:07
  • Trying it without binary logs would reduce the number of culprits by 1, or to 1. By default, starting with MariaDB 10.5.7, we’d steadily have up to 90% dirty pages in the buffer pool. You could work around this problem by explicitly triggering a checkpoint before starting to access lots of tables. Either SET GLOBAL innodb_max_dirty_pages_pct_lwm=1; (or some suitable number) to enable idle flushing at all times, or SET GLOBAL innodb_max_dirty_pages_pct=0; and wait some time for the data pages to be written out.
    – Marko Mäkelä
    Commented Jan 27, 2022 at 6:16
0

If you want to test the very latest MariaDB (non-Enterprise) server 10.5, you can use the quay.io/mariadb-foundation/mariadb-debug:10.5 that contains debug symbols and a debugger.

After initializing the datadir:

podman run -ti -v db105:/var/lib/mysql --user mysql \
   --cap-add CAP_SYS_PTRACE --name mdb105 \
   quay.io/mariadb-foundation/mariadb-debug:10.5 \
   gdb --args mysqld

Do what you need to trigger your bug:

When you get the SEGV:

(gdb) set logging file /var/lib/mysql/gdb_output.txt
(gdb) set pagination off
(gdb) set logging on
Copying output to /var/lib/mysql/gdb_output.txt.
Copying debug output to /var/lib/mysql/gdb_output.txt.
(gdb) thread apply all bt -frame-arguments all full

After its all stopped:

podman cp mdb105:/var/lib/mysql/gdb_output.txt  /tmp
podman cp mdb105:/manifest.txt  /tmp

and put those two items in a bug report/support ticket.

The manifest has information about the exact source code version where it was built.

ref: mariadb blog on debug containers

Improve this answer
11
  • Thank you! That debug container might accidentally fix the bug as well. I just remembered the checkpoint hang jira.mariadb.org/browse/MDEV-27416 that is fixed in the upcoming 10.5.14 release. I believe that the bug only affects scenarios where at most one connection is performing writes at a time.
    – Marko Mäkelä
    Commented Jan 27, 2022 at 6:57
  • Ah, if you don't need the debug capabilities quay.io/mariadb-foundation/mariadb-devel:10.5 is a more cutdown version until the next release.
    – danblack
    Commented Jan 27, 2022 at 7:40
  • As @MarkoMäkelä said in my scenario only one thread keep writing with mysqldump. with pipe restore to target DB container. SET GLOBAL innodb_max_dirty_pages_pct_lwm=1; that value should be in decimal isn't? default value 0.000000, 27 ... 2022-01-31T10:48:42.757627930+00:00 stderr F 2022-01-31 10:48:42 0 [ERROR] Invalid decimal value for option 'innodb-max-dirty-pages-pct-lwm' 2022-01-31T10:48:42.757627930+00:00 stderr F 2022-01-31T10:48:42.757627930+00:00 stderr F 2022-01-31 10:48:42 0 [ERROR] mysqld: Error while setting value '10;' to 'innodb-max-dirty-pages-pct-lwm'
    – Gopinath Karangula
    Commented Jan 31, 2022 at 12:10
  • +--------------------------------+----------+ | Variable_name | Value | +--------------------------------+----------+ | Innodb_buffer_pool_pages_dirty | 4035 | | Innodb_buffer_pool_bytes_dirty | 66109440 | +--------------------------------+----------+ My Data Migration Test on going, good to see the status of Query | 0 | starting | Query | 0 | Update Commit, Freeing Items in process list :) after innodb_max_dirty_pages_pct=0;
    – Gopinath Karangula
    Commented Jan 31, 2022 at 12:29
  • No luck even after innodb_max_dirty_pages_pct=0; 2022-01-31 12:33:09 368 [Note] InnoDB: Cannot close file because of 1 pending operations [Note] InnoDB: Cannot close file because of pending fsync Btw I have my Encryption Enabled, if this is causing problem, my next attempt will try disabling encryption. Also I have disabled sync_binlog, increase size of bin log from 200 M to 1G... mostly I will again hit with bug.
    – Gopinath Karangula
    Commented Jan 31, 2022 at 12:39

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.