[MDEV-10105] Mariadb initialize a shut down just after starting Created: 2016-05-23  Updated: 2016-09-22  Resolved: 2016-09-22

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.1.14
Fix Version/s: 10.1.18

Type: Bug Priority: Critical
Reporter: Yoann PANIER Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Environment:

Debian GNU/Linux 8.4 (jessie)
Kernel : 3.14.32-xxxx-grs-ipv6-64
Ram: 126Go
Disk: Raid 5

Issue Links:
Blocks
is blocked by MDEV-9931 InnoDB reads first page of every .ibd... Closed

 Description   

Hello,

I've just encountered an issue with my setup and don't understand what happen...

I've made a fresh install some days ago, tweak some settings, restart mariadb, and started to import thousands of tables through ssh because I had a problem with xtrabackup.

My import process finished, i decided to shutdown mariadb to change the bind-adress et try to restart it ..... CRASH

My first doubt was when i was watching the log and seen it hang on the message :"Highest supported file format is Barracuda."

After 5min, the process has continued but starts a shutdown just after the message : "/usr/sbin/mysqld: ready for connections."

I've tried to restart it multiple times with the same result.....

See bellow the log:

2016-05-23 18:31:14 131118867564480 [Note] Using unique option prefix 'myisam-recover' is error-prone and can break in the future. Please use the full name 'myisam-recover-options' instead.
 
2016-05-23 18:31:14 131118867564480 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2016-05-23 18:31:14 131118867564480 [Note] InnoDB: The InnoDB memory heap is disabled
 
2016-05-23 18:31:14 131118867564480 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-05-23 18:31:14 131118867564480 [Note] InnoDB: Memory barrier is not used
 
2016-05-23 18:31:14 131118867564480 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2016-05-23 18:31:14 131118867564480 [Note] InnoDB: Using Linux native AIO
 
2016-05-23 18:31:14 131118867564480 [Note] InnoDB: Using SSE crc32 instructions
 
2016-05-23 18:31:14 131118867564480 [Note] InnoDB: Initializing buffer pool, size = 80.0G
 
2016-05-23 18:31:18 131118867564480 [Note] InnoDB: Completed initialization of buffer pool
 
2016-05-23 18:31:18 131118867564480 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-05-23 18:37:03 131118867564480 [Note] InnoDB: 128 rollback segment(s) are active.
 
2016-05-23 18:37:03 131118867564480 [Note] InnoDB: Waiting for purge to start
 
2016-05-23 18:37:03 131118867564480 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.29-76.2 started; log sequence number 5149822398415
 
2016-05-23 18:37:03 131024369362688 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2016-05-23 18:37:03 131118867564480 [Note] Plugin 'FEEDBACK' is disabled.
 
2016-05-23 18:37:04 131118867564480 [Note] Server socket created on IP: '127.0.0.1'.
 
2016-05-23 18:37:04 131118865778432 [Note] /usr/sbin/mysqld: Normal shutdown
 
 
 
2016-05-23 18:37:04 131118867564480 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.1.14-MariaDB-1~jessie'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
 
2016-05-23 18:37:04 131118865778432 [Note] Event Scheduler: Purging the queue. 0 events
 
2016-05-23 18:37:04 131024351069952 [Note] InnoDB: FTS optimize thread exiting.
 
2016-05-23 18:37:04 131118865778432 [Note] InnoDB: Starting shutdown...
 
2016-05-23 18:37:10 131118865778432 [Note] InnoDB: Shutdown completed; log sequence number 5149822398425
 
2016-05-23 18:37:10 131118865778432 [Note] /usr/sbin/mysqld: Shutdown complete

And this is my.cnf:

sudo egrep -v "^#" /etc/mysql/my.cnf
 
 
 
[client]
 
port		= 3306
 
socket		= /var/run/mysqld/mysqld.sock
 
 
 
 
 
[mysqld_safe]
 
socket		= /var/run/mysqld/mysqld.sock
 
nice		= 0
 
 
 
[mysqld]
 
user		= mysql
 
pid-file	= /var/run/mysqld/mysqld.pid
 
socket		= /var/run/mysqld/mysqld.sock
 
port		= 3306
 
basedir		= /usr
 
datadir		= /var/lib/mysql
 
tmpdir		= /tmp
 
datadir         = /home/mysql/db
 
tmpdir          = /home/mysql/tmp
 
lc-messages-dir	= /usr/share/mysql
 
skip-external-locking
 
bind-address		= 127.0.0.1
 
key_buffer		= 16M
 
max_allowed_packet	= 16M
 
thread_stack		= 192K
 
thread_cache_size       = 128
 
bulk_insert_buffer_size = 16M
 
tmp_table_size          = 32M
 
max_heap_table_size     = 32M
 
 
 
myisam-recover         = BACKUP
 
max_connections        = 200
 
connect_timeout         = 5
 
wait_timeout            = 600
 
query_cache_limit	= 1M
 
query_cache_size        = 64M
 
log_error = /var/log/mysql/error.log
 
server-id		= 1
 
log_bin			= /home/mysql/log/mysql-bin.log
 
expire_logs_days	= 5
 
max_binlog_size         = 100M
 
default_storage_engine  = InnoDB
 
innodb_log_file_size    = 1G
 
innodb_log_files_in_group       = 8
 
innodb_buffer_pool_size = 80G
 
innodb_log_buffer_size  = 16M
 
innodb_file_per_table   = 1
 
innodb_open_files       = 400
 
innodb_io_capacity      = 400
 
innodb_flush_method     = O_DIRECT
 
 
 
innodb_thread_concurrency       = 32
 
innodb_log_group_home_dir       = /home/mysql/redo
 
innodb_file_format      = Barracuda
 
 
 
 
 
 
 
 
 
[mysqldump]
 
quick
 
quote-names
 
max_allowed_packet	= 16M
 
 
 
[mysql]
 
 
 
[isamchk]
 
key_buffer		= 16M
 
 
 
!includedir /etc/mysql/conf.d/

I hope you will have good news for me because I've spent many hours for this migration :-/

Best regards,

 Comments   
Comment by Yoann PANIER [ 2016-05-24 ]

I tried to reinstall mariadb-server but a new problem has come...

apt-get purge mariadb-server

Reading package lists... Done
 
Building dependency tree       
Reading state information... Done
 
The following packages were automatically installed and are no longer required:
 
  galera-3 libhtml-template-perl libjemalloc1 libperl4-corelibs-perl lsof mariadb-client-10.1 mariadb-client-core-10.1 mariadb-server-10.1 mariadb-server-core-10.1 socat
 
Use 'apt-get autoremove' to remove them.
 
The following packages will be REMOVED:
 
  mariadb-server*
 
0 upgraded, 0 newly installed, 1 to remove and 6 not upgraded.
 
After this operation, 27,6 kB disk space will be freed.
 
Do you want to continue? [Y/n] Y
 
(Reading database ... 26324 files and directories currently installed.)
 
Removing mariadb-server (10.1.14+maria-1~jessie) ...

apt-get autoremove

Reading package lists... Done
 
Building dependency tree       
Reading state information... Done
 
The following packages will be REMOVED:
 
  galera-3 libhtml-template-perl libjemalloc1 libperl4-corelibs-perl lsof mariadb-client-10.1 mariadb-client-core-10.1 mariadb-server-10.1 mariadb-server-core-10.1 socat
 
0 upgraded, 0 newly installed, 10 to remove and 6 not upgraded.
 
After this operation, 171 MB disk space will be freed.
 
Do you want to continue? [Y/n] Y
 
(Reading database ... 26321 files and directories currently installed.)
 
Removing mariadb-server-10.1 (10.1.14+maria-1~jessie) ...
 
Removing galera-3 (25.3.15-jessie) ...
 
Removing libhtml-template-perl (2.95-1) ...
 
Removing mariadb-server-core-10.1 (10.1.14+maria-1~jessie) ...
 
Removing libjemalloc1 (3.6.0-3) ...
 
Removing lsof (4.86+dfsg-1) ...
 
Removing libperl4-corelibs-perl (0.003-1) ...
 
Removing mariadb-client-10.1 (10.1.14+maria-1~jessie) ...
 
Removing mariadb-client-core-10.1 (10.1.14+maria-1~jessie) ...
 
Removing socat (1.7.2.4-2) ...
 
Processing triggers for man-db (2.7.0.2-5) ...
 
Processing triggers for libc-bin (2.19-18+deb8u4) ...

apt-get install mariadb-server

Reading package lists... Done
 
Building dependency tree       
Reading state information... Done
 
The following extra packages will be installed:
 
  galera-3 libhtml-template-perl libjemalloc1 libperl4-corelibs-perl lsof mariadb-client-10.1 mariadb-client-core-10.1 mariadb-server-10.1 mariadb-server-core-10.1 socat
 
Suggested packages:
 
  libipc-sharedcache-perl libterm-readkey-perl mailx mariadb-test netcat-openbsd tinyca
 
The following NEW packages will be installed:
 
  galera-3 libhtml-template-perl libjemalloc1 libperl4-corelibs-perl lsof mariadb-client-10.1 mariadb-client-core-10.1 mariadb-server mariadb-server-10.1 mariadb-server-core-10.1 socat
 
0 upgraded, 11 newly installed, 0 to remove and 6 not upgraded.
 
Need to get 0 B/20,3 MB of archives.
 
After this operation, 171 MB of additional disk space will be used.
 
Do you want to continue? [Y/n] Y
 
Preconfiguring packages ...
 
Selecting previously unselected package galera-3.
 
(Reading database ... 25952 files and directories currently installed.)
 
Preparing to unpack .../galera-3_25.3.15-jessie_amd64.deb ...
 
Unpacking galera-3 (25.3.15-jessie) ...
 
Selecting previously unselected package libperl4-corelibs-perl.
 
Preparing to unpack .../libperl4-corelibs-perl_0.003-1_all.deb ...
 
Unpacking libperl4-corelibs-perl (0.003-1) ...
 
Selecting previously unselected package lsof.
 
Preparing to unpack .../lsof_4.86+dfsg-1_amd64.deb ...
 
Unpacking lsof (4.86+dfsg-1) ...
 
Selecting previously unselected package mariadb-client-core-10.1.
 
Preparing to unpack .../mariadb-client-core-10.1_10.1.14+maria-1~jessie_amd64.deb ...
 
Unpacking mariadb-client-core-10.1 (10.1.14+maria-1~jessie) ...
 
Selecting previously unselected package mariadb-client-10.1.
 
Preparing to unpack .../mariadb-client-10.1_10.1.14+maria-1~jessie_amd64.deb ...
 
Unpacking mariadb-client-10.1 (10.1.14+maria-1~jessie) ...
 
Selecting previously unselected package libjemalloc1.
 
Preparing to unpack .../libjemalloc1_3.6.0-3_amd64.deb ...
 
Unpacking libjemalloc1 (3.6.0-3) ...
 
Selecting previously unselected package mariadb-server-core-10.1.
 
Preparing to unpack .../mariadb-server-core-10.1_10.1.14+maria-1~jessie_amd64.deb ...
 
Unpacking mariadb-server-core-10.1 (10.1.14+maria-1~jessie) ...
 
Selecting previously unselected package socat.
 
Preparing to unpack .../socat_1.7.2.4-2_amd64.deb ...
 
Unpacking socat (1.7.2.4-2) ...
 
Selecting previously unselected package mariadb-server-10.1.
 
Preparing to unpack .../mariadb-server-10.1_10.1.14+maria-1~jessie_amd64.deb ...
 
Failed to stop mysql.service: Unit mysql.service not loaded.
 
invoke-rc.d: initscript mysql, action "stop" failed.
 
invoke-rc.d returned 5
 
There is a MySQL server running, but we failed in our attempts to stop it.
 
Stop it yourself and try again!
 
dpkg: error processing archive /var/cache/apt/archives/mariadb-server-10.1_10.1.14+maria-1~jessie_amd64.deb (--unpack):
 
 subprocess new pre-installation script returned error exit status 1
 
Selecting previously unselected package libhtml-template-perl.
 
Preparing to unpack .../libhtml-template-perl_2.95-1_all.deb ...
 
Unpacking libhtml-template-perl (2.95-1) ...
 
Selecting previously unselected package mariadb-server.
 
Preparing to unpack .../mariadb-server_10.1.14+maria-1~jessie_all.deb ...
 
Unpacking mariadb-server (10.1.14+maria-1~jessie) ...
 
Processing triggers for man-db (2.7.0.2-5) ...
 
E: Sub-process /usr/bin/dpkg returned an error code (1)

There is a MySQL server running, but we failed in our attempts to stop it.
Stop it yourself and try again!

But i can't find a Mysql process....

lsof | grep mysql --> return nothing
ps aux | grep mysql --> return the grep himself
ls -rtl /var/run/mysqld/ --> cannot access /var/run/mysqld/: No such file or directory

Best regards,

Comment by Yoann PANIER [ 2016-05-24 ]

I've moved temporarily the file /etc/init.d/mysql to complete the install.... and the problem still remain

I used this stap script provided by the percona blog :

probe signal.send, signal.systgkill {
 
  if (sig_name == "SIGKILL" || sig_name == "SIGTERM")
 
    printf("[%s] %s was sent to %s (pid:%d) by %s (pid: %d, tid:%d) uid:%dn",
 
        ctime(gettimeofday_s()),
 
        sig_name,
 
        pid_name,
 
        sig_pid,
 
        execname(),
 
        pid(),
 
        tid(),
 
        uid()
 
    )
 
}

and I discover that the process who kill MySQL is systemd .....

So I managed to bypass this problem by add "TimeoutStartSec=10m" to the service file but I'm feeling guilty to apply this trick.

Is there any reasons who justify than my Mariadb server take so long to start ?
I didn't had this issue with previous versions and the same config (but Mariadb was launched by a init.d script instead of systemd who don't send a SIGTERM to the process in previous Debian version if I'm not wrong)

Best regards,

Comment by Elena Stepanova [ 2016-05-27 ]

If you paste the error log which relates to the 10-min startup, we might see what exactly takes so long (not only the one from the file, but whatever relates to mysqld in the journal).

Initializing 80G buffer pool and creating 8 logs 1G each might take long, I guess it depends on the machine whether it takes this long. If the logs took most of the time, the problem should be gone after the first startup – logs have already been created, so restarts should be faster. If it's the buffer pool to blame, then it will be happening every time. If it's something else, we need to see what exactly it is.

Comment by Yoann PANIER [ 2016-05-27 ]

I already restarted it a few times and it takes every time a few minutes (~7min the last one)

Mysql Error log for the last restart:

2016-05-25 12:03:29 139751295538944 [Note] /usr/sbin/mysqld: Normal shutdown
 
 
 
2016-05-25 12:03:29 139751295538944 [Note] Event Scheduler: Purging the queue. 0 events
 
2016-05-25 12:03:29 139656859444992 [Note] InnoDB: FTS optimize thread exiting.
 
2016-05-25 12:03:29 139751295538944 [Note] InnoDB: Starting shutdown...
 
2016-05-25 12:03:58 139751295538944 [Note] InnoDB: Shutdown completed; log sequence number 5285398145056
 
2016-05-25 12:03:58 139751295538944 [Note] /usr/sbin/mysqld: Shutdown complete
 
 
 
2016-05-25 12:03:59 140377057724352 [Note] Using unique option prefix 'myisam-recover' is error-prone and can break in the future. Please use the full name 'myisam-recover-options'
 
 instead.
 
2016-05-25 12:03:59 140377057724352 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2016-05-25 12:03:59 140377057724352 [Note] InnoDB: The InnoDB memory heap is disabled
 
2016-05-25 12:03:59 140377057724352 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-05-25 12:03:59 140377057724352 [Note] InnoDB: Memory barrier is not used
 
2016-05-25 12:03:59 140377057724352 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2016-05-25 12:03:59 140377057724352 [Note] InnoDB: Using Linux native AIO
 
2016-05-25 12:03:59 140377057724352 [Note] InnoDB: Using SSE crc32 instructions
 
2016-05-25 12:03:59 140377057724352 [Note] InnoDB: Initializing buffer pool, size = 80.0G
 
2016-05-25 12:04:03 140377057724352 [Note] InnoDB: Completed initialization of buffer pool
 
2016-05-25 12:04:03 140377057724352 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-05-25 12:11:46 140377057724352 [Note] InnoDB: 128 rollback segment(s) are active.
 
2016-05-25 12:11:46 140377057724352 [Note] InnoDB: Waiting for purge to start
 
2016-05-25 12:11:46 140377057724352 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.29-76.2 started; log sequence number 5285398145056
 
2016-05-25 12:11:46 140377057724352 [Note] Plugin 'FEEDBACK' is disabled.
 
2016-05-25 12:11:46 140282548946688 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2016-05-25 12:11:47 140377057724352 [Note] Server socket created on IP: '0.0.0.0'.
 
2016-05-25 12:11:47 140377057724352 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.1.14-MariaDB-1~jessie'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

From journalctl:

sudo journalctl | grep mysqld | grep "mai 25 12"
 
mai 25 12:03:59 xxxx.xxxx.fr mysqld[6441]: 2016-05-25 12:03:59 140377057724352 [Note] Using unique option prefix 'key_buffer' is error-prone and can break in the future. Please use the full name 'key_buffer_size' instead.
 
mai 25 12:03:59 xxxx.xxxx.fr mysqld[6441]: 2016-05-25 12:03:59 140377057724352 [Note] /usr/sbin/mysqld (mysqld 10.1.14-MariaDB-1~jessie) starting as process 6441 ...
 
mai 25 12:11:48 xxxx.xxxx.fr mysqld[6832]: Checking for corrupt, not cleanly closed and upgrade needing tables.

I don't find other information related to mysqld in /var/log

Comment by Elena Stepanova [ 2016-06-10 ]

So, the delay is here:

2016-05-25 12:04:03 140377057724352 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-05-25 12:11:46 140377057724352 [Note] InnoDB: 128 rollback segment(s) are active.

It must be MDEV-9931.

Comment by Jan Lindström (Inactive) [ 2016-09-22 ]

commit 2bedc3978b90bf5abe1029df393c63ced1849bed
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Thu Sep 22 16:32:26 2016 +0300
MDEV-9931: InnoDB reads first page of every .ibd file at startup
Analysis: By design InnoDB was reading first page of every .ibd file
at startup to find out is tablespace encrypted or not. This is
because tablespace could have been encrypted always, not
encrypted newer or encrypted based on configuration and this
information can be find realible only from first page of .ibd file.
Fix: Do not read first page of every .ibd file at startup. Instead
whenever tablespace is first time accedded we will read the first
page to find necessary information about tablespace encryption
status.
TODO: Add support for SYS_TABLEOPTIONS where all table options
encryption information included will be stored.

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