[MDEV-8743] galera in SST keeps innodb files open Created: 2015-09-04  Updated: 2018-06-21  Resolved: 2018-05-09

Status: Closed
Project: MariaDB Server
Component/s: Galera SST, Storage Engine - Aria, Storage Engine - InnoDB, Storage Engine - MyISAM, XA
Affects Version/s: 10.0.21-galera
Fix Version/s: 10.1.33, 10.2.15, 10.3.7, 10.0.36-galera

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: contribution, foundation, galera, patch
Environment:

rhel6

Issue Links:
Problem/Incident
causes MDEV-16548 Innodb fails to start on older kernel... Closed
Relates
relates to MDEV-7631 Invalid WSREP_SST rows appear in mysq... Closed

 Description   

MDEV-7631 was closing off files when SST processes where executed. Some where missed.

This was the tar process generating a tar of binlogs on a rsync donor with all the innodb files open.

lsof -p

{tarpid} 

tar     3825 mysql  cwd    DIR   253,0       40960 2997037 /var/lib/mysql
 
tar     3825 mysql  rtd    DIR   253,0        4096       2 /
 
tar     3825 mysql  txt    REG   253,0      390616  261280 /bin/tar
 
tar     3825 mysql  mem    REG   253,0       65928  651690 /lib64/libnss_files-2.12.so
 
tar     3825 mysql  mem    REG   253,0      142640  651563 /lib64/libpthread-2.12.so
 
tar     3825 mysql  mem    REG   253,0       18712  651585 /lib64/libattr.so.1.1.0
 
tar     3825 mysql  mem    REG   253,0       19536  651672 /lib64/libdl-2.12.so
 
tar     3825 mysql  mem    REG   253,0     1921216  651539 /lib64/libc-2.12.so
 
tar     3825 mysql  mem    REG   253,0       43880  651724 /lib64/librt-2.12.so
 
tar     3825 mysql  mem    REG   253,0       31280  651601 /lib64/libacl.so.1.1.0
 
tar     3825 mysql  mem    REG   253,0      122040  651577 /lib64/libselinux.so.1
 
tar     3825 mysql  mem    REG   253,0      154664  651609 /lib64/ld-2.12.so
 
tar     3825 mysql    0r   CHR     1,3         0t0    3871 /dev/null
 
tar     3825 mysql    1w   REG   253,0    70925586 1045768 /var/log/mysql/error.log
 
tar     3825 mysql    2w   REG   253,0    70925586 1045768 /var/log/mysql/error.log
 
tar     3825 mysql    3u   CHR     5,0         0t0    5338 /dev/tty
 
tar     3825 mysql    4u   REG   253,0         110 2998607 /var/lib/mysql/grastate.dat
 
tar     3825 mysql    5w   REG   253,0 21542461440 2998605 /var/lib/mysql/wsrep_sst_binlog.tar
 
tar     3825 mysql    6u   REG     0,9           0    3869 [eventpoll]
 
tar     3825 mysql    7u   REG     0,9           0    3869 [timerfd]
 
tar     3825 mysql    8u   REG     0,9           0    3869 [eventfd]
 
tar     3825 mysql    9u   REG     0,9           0    3869 [eventpoll]
 
tar     3825 mysql   10u   REG     0,9           0    3869 [timerfd]
 
tar     3825 mysql   11u   REG     0,9           0    3869 [eventfd]
 
tar     3825 mysql   12r   REG   253,0 35721262759 2998690 /var/lib/mysql/mysql-bin.000061
 
tar     3825 mysql   14u   REG   253,0   297795584 2997039 /var/lib/mysql/ibdata1
 
tar     3825 mysql   15u   REG   253,0        5459  651645 /tmp/iblvW3eD (deleted)
 
tar     3825 mysql   16u   REG   253,0           0  651667 /tmp/ibIUPTrD (deleted)
 
tar     3825 mysql   17u   REG   253,0           0  651669 /tmp/ib55RJED (deleted)
 
tar     3825 mysql   18u   REG   253,0           0  651671 /tmp/ibWRMt4E (deleted)
 
tar     3825 mysql   19u   REG   253,0    67108864 2998611 /var/lib/mysql/ib_logfile0
 
tar     3825 mysql   20u   REG   253,0    67108864 2998612 /var/lib/mysql/ib_logfile1
 
tar     3825 mysql   21u   REG   253,0    67108864 2998613 /var/lib/mysql/ib_logfile2
 
tar     3825 mysql   22u   REG   253,0    67108864 2998614 /var/lib/mysql/ib_logfile3
 
tar     3825 mysql   23u   REG   253,0    67108864 2998615 /var/lib/mysql/ib_logfile4
 
tar     3825 mysql   24u   REG   253,0    67108864 2998616 /var/lib/mysql/ib_logfile5
 
tar     3825 mysql   25u   REG   253,0    67108864 2998617 /var/lib/mysql/ib_logfile6
 
tar     3825 mysql   26u   REG   253,0    67108864 2998618 /var/lib/mysql/ib_logfile7
 
tar     3825 mysql   27u   REG   253,0      589824 3258475 /var/lib/mysql/drupal_radio_prod/field_data_field_date_expires.ibd
 
tar     3825 mysql   28u   REG   253,0           0  651686 /tmp/ibbShLHG (deleted)
 
tar     3825 mysql   29u   REG   253,0      212992 3258333 /var/lib/mysql/drupal_radio_prod/field_data_field_file_image_title_text.ibd
 
...
 
(more ibd files)



 Comments   
Comment by Ragnar Rova [ 2015-09-04 ]

I've opened https://github.com/codership/galera/issues/339 for grastate.dat

Comment by Daniel Black [ 2015-09-04 ]

good call. thanks rrva.

Comment by Daniel Black [ 2018-03-02 ]

Pull requests attached close all the common files I've found/seen and still leave stderr/stdout for SST scripts and the wsrep_notify_cmd.

Edit: fopen calls corrected in PR #638. STR_O_CLOEXEC (aka "e") needs to be at the end of the fopen mode. As such buffer pool dump/restore now also protected from manipulation.

2018-03-05 11:58:47 0 [Note] InnoDB: 5.7.21 started; log sequence number 1632558; transaction id 22
 
2018-03-05 11:58:47 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/datadir/ib_buffer_pool
 
2018-03-05 11:58:47 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2018-03-05 11:58:47 0 [Note] InnoDB: Buffer pool(s) load completed at 180305 11:58:47
 
2018-03-05 11:58:47 0 [Note] Reading of all Master_info entries succeded
 
2018-03-05 11:58:47 0 [Note] Added new Master_info '' to hash table
 
2018-03-05 11:58:47 0 [Note] sql/mysqld: ready for connections.
 
Version: '10.3.6-MariaDB-log'  socket: '/tmp/s.sock'  port: 0  Source distribution
 
2018-03-05 11:59:16 0 [Note] sql/mysqld (root[root] @ localhost []): Normal shutdown
 
2018-03-05 11:59:16 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2018-03-05 11:59:16 0 [Note] InnoDB: FTS optimize thread exiting.
 
2018-03-05 11:59:16 0 [Note] InnoDB: Starting shutdown...
 
2018-03-05 11:59:16 0 [Note] InnoDB: Dumping buffer pool(s) to /tmp/datadir/ib_buffer_pool
 
2018-03-05 11:59:16 0 [Note] InnoDB: Buffer pool(s) dump completed at 180305 11:59:16
 
2018-03-05 11:59:17 0 [Note] InnoDB: Shutdown completed; log sequence number 1632567; transaction id 23

Comment by Daniel Black [ 2018-03-05 ]

wlad does opening files with O_CLOEXEC interfere with mariabackup in anyway?

Comment by Vladislav Vaintroub [ 2018-03-05 ]

danblack, it does not interfere with backup

Comment by Jan Lindström (Inactive) [ 2018-03-14 ]

commit 930682c4877b66417184c1787fab7941c9331c34
Merge: 7bd95307f2a 26e4a48bda8
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Mar 14 09:38:04 2018 +0200

Merge pull request #636 from grooverdan/10.0-galera-MDEV-8743-linux-aio-ib_logfile0

MDEV-8743: ib_logfile0 Use O_CLOEXEC so galera SST scripts don't get fd

commit 26e4a48bda8a09ac4ddef64e12841fbee29f4d7d
Author: Daniel Black <daniel@linux.vnet.ibm.com>
Date: Fri Mar 2 10:50:38 2018 +1100

MDEV-8743: ib_logfile0 Use O_CLOEXEC so galera SST scripts don't get fd

Comment by Elena Stepanova [ 2018-03-16 ]

danblack, jplindst,
Merged pull request #640 has broken 10.3 tree, MTR tests from galera suite fail massively (possibly any tests which start more than one node and use rsync).
Please fix and do run MTR tests before pushing.

Comment by Daniel Black [ 2018-03-17 ]

Looking at http://buildbot.askmonty.org/buildbot/builders/kvm-deb-artful-x86/builds/738/steps/mtr/logs/stdio

head @ c231a228ca4bec214dde86ab8335473bc0db7a08
 
 
 
$ mysql-test/mysql-test-run --mem  wsrep_info.plugin galera.galera_binlog_checksum galera.galera_binlog_event_max_size_min galera.MW-313 galera.galera_mdev_13787
 
Logging: /home/dan/software_projects/mariadb-server/mysql-test/mysql-test-run.pl  --mem wsrep_info.plugin galera.galera_binlog_checksum galera.galera_binlog_event_max_size_min galera.MW-313 galera.galera_mdev_13787
 
vardir: /home/dan/software_projects/build-mariadb-10.3-debug/mysql-test/var
 
Checking leftover processes...
 
Removing old var directory...
 
Creating var directory '/home/dan/software_projects/build-mariadb-10.3-debug/mysql-test/var'...
 
 - symlinking 'var' to '/dev/shm/var_auto_EART'
 
Checking supported features...
 
MariaDB Version 10.3.6-MariaDB-debug
 
 - SSL connections supported
 
 - binaries are debug compiled
 
Collecting tests...
 
Installing system database...
 
 
 
==============================================================================
 
 
 
TEST                                      RESULT   TIME (ms) or COMMENT
 
--------------------------------------------------------------------------
 
 
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
 
galera.galera_binlog_checksum 'innodb'   [ pass ]   2086
 
galera.MW-313 'innodb'                   [ pass ]   2110
 
galera.galera_binlog_event_max_size_min 'innodb' [ pass ]   2088
 
galera.galera_mdev_13787 'innodb'        [ pass ]   2082
 
wsrep_info.plugin 'innodb'               [ pass ]   2023
 
 
 
 bash --version
 
GNU bash, version 4.4.19(1)-release (x86_64-redhat-linux-gnu)

Full galera suite:

build-mariadb-10.3-debug $ mysql-test/mysql-test-run --mem --parallel=4 --big-test --suite galera --max-test-fail=40 --force
 
 
 
..
 
Check of testcase failed for: galera.galera_many_rows
 
 
 
Completed: Failed 16/198 tests, 91.92% were successful.
 
 
 
Failing test(s): galera.MW-86-wait1 galera.galera_fulltext galera.galera_autoinc_sst_xtrabackup galera.galera_ist_innodb_flush_logs galera.galera_sst_mysqldump_with_key galera.galera_sst_xtrabackup-v2-options galera.galera_ist_rsync galera.galera_sst_xtrabackup-v2 galera.galera_sst_rsync galera.galera_ist_xtrabackup-v2 galera.galera_sst_xtrabackup-v2_encrypt_with_key galera.galera_wan_restart_ist galera.galera_sst_mysqldump galera.MW-388 galera.galera_many_tables_nopk galera.galera_parallel_autoinc_manytrx

Retrying the following tests managed to pass:

galera.galera_fulltext 'innodb'          [ pass ]  18997
 
galera.galera_many_tables_nopk 'innodb'  [ pass ]  27977
 
galera.galera_parallel_autoinc_manytrx 'innodb' [ pass ]  17992
 
galera.MW-388 'innodb'                   [ pass ]   4124

With #640 reverted, trying these tests still mostly failed.

Completed: Failed 11/16 tests, 31.25% were successful.
 
 
 
Failing test(s): galera.MW-86-wait1 galera.galera_autoinc_sst_xtrabackup galera.galera_ist_innodb_flush_logs galera.galera_ist_rsync galera.galera_ist_xtrabackup-v2 galera.galera_sst_mysqldump galera.galera_sst_mysqldump_with_key galera.galera_sst_rsync galera.galera_sst_xtrabackup-v2-options galera.galera_sst_xtrabackup-v2 galera.galera_sst_xtrabackup-v2_encrypt_with_key

Testing in dash (Ubuntu:artful x86_64) adding a set -x -v to wsrep_sst_common

2018-03-17  9:03:17 0 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'joiner' --address '127.0.0.1:16007' --datadir '/build/builddir/mysql-test/var/1/mysqld.2/data/'  --d
 
efaults-file '/build/builddir/mysql-test/var/1/my.cnf' --defaults-group-suffix '.2'  --parent '19914' --binlog 'mysqld-bin' '
 
 
 
if [ -d /proc/self/fd ]; then
 
  for fd in /proc/self/fd/*; do
 
    fd=${fd##*/}
 
    #/bin/ls -la /proc/self/fd/${fd} >2
 
    # While bash would support the below syntax other sh's don't
 
    #[ $fd -gt 2 ] && exec {fd}>&-
 
    [ $fd -gt 2 ] && eval "exec ${fd}>&-" 2> /dev/null
 
  done
 
else
 
  upper_no_file=$(ulimit -n)
 
  [ "$upper_no_file" = "unlimited" ] || [ -z "$upper_no_file" ] && upper_no_file=1024
 
 
 
  while [ $upper_no_file -gt 2 ]
 
  do
 
     eval "exec ${upper_no_file}>&-"
 
     upper_no_file=$(( "$upper_no_file" - 1 ))
 
  done
 
fi
 
+ [ -d /proc/self/fd ]
 
+ fd=0
 
+ [ 0 -gt 2 ]
 
+ :
 
+ fd=1
 
+ [ 1 -gt 2 ]
 
+ :
 
+ fd=10
 
+ [ 10 -gt 2 ]
 
+ eval exec 10>&-
 
2018-03-17  9:03:17 0 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_rsync --role 'joiner' --address '127.0.0.1:16007' --datadir '/build/builddir/mysql-test
 
/var/1/mysqld.2/data/'  --defaults-file '/build/builddir/mysql-test/var/1/my.cnf' --defaults-group-suffix '.2'  --parent '19914' --binlog 'mysqld-bin'
 
        Read: '(null)'
 
2018-03-17  9:03:17 0 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'joiner' --address '127.0.0.1:16007' --datadir '/build/builddir/mysql-test/var/1
 
/mysqld.2/data/'  --defaults-file '/build/builddir/mysql-test/var/1/my.cnf' --defaults-group-suffix '.2'  --parent '19914' --binlog 'mysqld-bin' : 2 (No such file or dire
 
ctory)
 
2018-03-17  9:03:17 2 [ERROR] WSREP: Failed to prepare for 'rsync' SST. Unrecoverable.
 
2018-03-17  9:03:17 2 [ERROR] Aborting

So it seems dash isn't liking the close on fd 10. Attempting to look at it with ls -la /proc/self/fds doesn't list it. Bit odd.

Comment by Elena Stepanova [ 2018-03-17 ]

From the whole picture http://buildbot.askmonty.org/buildbot/grid?category=main&branch=10.3&width=8 it's rather obvious that the problem is not limited to artful.
And I'm getting it just as easily on my local Jessie (which also symlinks /bin/sh to dash by default).

$ git log -1
 
commit 1a0b573b2b099c170efa2eb803e5221724fa2244
 
 
 
wsrep_info.plugin 'innodb'               [ fail ]
 
        Test ended at 2018-03-17 12:06:59
 
 
 
CURRENT_TEST: wsrep_info.plugin
 
 
 
 
 
Failed to start mysqld.2
 
mysqltest failed but provided no output


$ git log -1
 
commit f66a3159100dfb98025b63e92486b63cf3ba4aa3
 
 
 
wsrep_info.plugin 'innodb'               [ pass ]   2013

Comment by Jan Lindström (Inactive) [ 2018-03-17 ]

I will revert the change, I should have tested it more thoroughly.

Generated at Thu Feb 08 07:29:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.