Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.1.14
-
None
-
Debian GNU/Linux 8.4 (jessie)
Kernel : 3.14.32-xxxx-grs-ipv6-64
Ram: 126Go
Disk: Raid 5
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,
Attachments
Issue Links
- is blocked by
-
-
- Closed
-
Activity
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,
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.
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
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.
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.
I tried to reinstall mariadb-server but a new problem has come...
apt-get purge mariadb-server
Reading package lists... DoneBuilding dependency treeReading state information... DoneThe 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 socatUse '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... DoneBuilding dependency treeReading state information... DoneThe 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 socat0 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... DoneBuilding dependency treeReading state information... DoneThe 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 socatSuggested packages:libipc-sharedcache-perl libterm-readkey-perl mailx mariadb-test netcat-openbsd tinycaThe 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 socat0 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] YPreconfiguring 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 5There 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 1Selecting 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,