MySQL / MariaDB update error

dkzr

Verified User
Joined
Oct 17, 2013
Messages
94
Location
The Netherlands
For the last few times, when I update MariaDB I get the following error:

Code:
root@server:/usr/local/directadmin/custombuild# ./build update_versions
Updating MariaDB.
--2016-10-02 14:25:15--  http://files6.directadmin.com/services/all/mariadb/10.1/10.1.18/mariadb-10.1.18-linux-x86_64.tar.gz
Resolving files6.directadmin.com (files6.directadmin.com)... 2001:16e8:1:4:62:148:181:110, 62.148.181.110
Connecting to files6.directadmin.com (files6.directadmin.com)|2001:16e8:1:4:62:148:181:110|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 353318699 (337M) [application/x-gzip]
Saving to: ‘mariadb-10.1.18-linux-x86_64.tar.gz’

mariadb-10.1.18-linux-x86_64.tar.gz   100%[=========================================================================>] 336.95M  69.1MB/s   in 4.6s   

2016-10-02 14:25:19 (73.8 MB/s) - ‘mariadb-10.1.18-linux-x86_64.tar.gz’ saved [353318699/353318699]

mv: ‘mariadb-10.1.18-linux-x86_64.tar.gz’ and ‘/usr/local/mariadb-10.1.18-linux-x86_64.tar.gz’ are the same file
Stopping mysqld ...
Ensuring local-infile is disabled for security reasons in MySQL configuration file...
Giving mysqld a few seconds to start up...

[B]/usr/local/mysql/bin/mysqlcheck: Got error: 2002: Can't connect to local MySQL server through socket '/usr/local/mysql/data/mysql.sock' (2 "No such file or directory") when trying to connect
FATAL ERROR: Upgrade failed[/B]

Restarting MySQL.

Perhaps the timing between starting MariaDB and doing the check is too short?

When I check for the socket file (after the error) it does exist and the update is done (according to `mysqlcheck --version`)
 
Hello,

Check the mysql error log, probably your server was recovering or fixing some data, thus it took a bit longer time to start.
 
Ah, there was a rollback of 128 active segments (?) that took about 9 seconds. That's probably the issue then...
 
Hi, bumping this thread.

With every update I still get the same error. Below the output from the ./build script and the MariaDB error log output.

Does anybody else have this issue? Is there a way to solve it?

My server is running Debian 8.10

Thanks!

Code:
root@<server>:/usr/local/directadmin/custombuild# ./build update_versions
Updating MariaDB.
--2018-05-14 11:15:26--  http://files6.directadmin.com/services/all/mariadb/10.1/10.1.33/mariadb-10.1.33-linux-x86_64.tar.gz
Resolving files6.directadmin.com (files6.directadmin.com)... 2001:16e8:1:c:62:148:174:106, 62.148.174.106
Connecting to files6.directadmin.com (files6.directadmin.com)|2001:16e8:1:c:62:148:174:106|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 402308594 (384M) [application/x-gzip]
Saving to: ‘mariadb-10.1.33-linux-x86_64.tar.gz’

mariadb-10.1.33-lin 100%[=====================>] 383.67M  59.4MB/s   in 6.4s   

2018-05-14 11:15:32 (59.7 MB/s) - ‘mariadb-10.1.33-linux-x86_64.tar.gz’ saved [402308594/402308594]

mv: ‘mariadb-10.1.33-linux-x86_64.tar.gz’ and ‘/usr/local/mariadb-10.1.33-linux-x86_64.tar.gz’ are the same file
Stopping mysqld ...
Ensuring local-infile is disabled for security reasons in MySQL configuration file...
Giving mysqld a few seconds to start up...
/usr/local/mysql/bin/mysqlcheck: Got error: 2002: Can't connect to local MySQL server through socket '/usr/local/mysql/data/mysql.sock' (2 "No such file or directory") when trying to connect
FATAL ERROR: Upgrade failed
Restarting MySQL.
root@<server>:/usr/local/directadmin/custombuild#


Below the error log. I did a restart first (did not help). The upgrade sequence starts around the bold line.

Code:
2018-05-09 17:35:51 140166627547008 [Note] InnoDB: Waiting for purge to start
2018-05-09 17:35:51 140166627547008 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.38-83.0 started; log sequence number 189914458347
2018-05-09 15:36:26 140165901182720 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-05-09 15:36:26 140166627547008 [Note] Plugin 'FEEDBACK' is disabled.
2018-05-09 15:36:26 140166627547008 [Note] Server socket created on IP: '127.0.0.1'.
2018-05-09 15:36:27 140166627547008 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '10.1.32-MariaDB'  socket: '/usr/local/mysql/data/mysql.sock'  port: 3306  MariaDB Server
2018-05-14 11:14:10 140166281345792 [Note] /usr/local/mysql/bin/mysqld: Normal shutdown
2018-05-14 11:14:10 140166281345792 [Note] Event Scheduler: Purging the queue. 0 events
2018-05-14 11:14:10 140165951493888 [Note] InnoDB: FTS optimize thread exiting.
2018-05-14 11:14:10 140166281345792 [Note] InnoDB: Starting shutdown...
2018-05-14 11:14:11 140166281345792 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-05-14 11:14:12 140166281345792 [Note] InnoDB: Shutdown completed; log sequence number 190262289031
2018-05-14 11:14:12 140166281345792 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

180514 11:14:12 mysqld_safe mysqld from pid file /usr/local/mysql/data/mysqld.pid ended
180514 11:14:13 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2018-05-14 11:14:13 140181707237248 [Note] /usr/local/mysql/bin/mysqld (mysqld 10.1.32-MariaDB) starting as process 16239 ...
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: The InnoDB memory heap is disabled
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Using Linux native AIO
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Using generic crc32 instructions
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Completed initialization of buffer pool
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Highest supported file format is Barracuda.
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: 128 rollback segment(s) are active.
2018-05-14 11:14:13 140181707237248 [Note] InnoDB: Waiting for purge to start
2018-05-14 11:14:13 140181707237248 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.38-83.0 started; log sequence number 190262289031
2018-05-14 11:14:13 140180971321088 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-05-14 11:14:13 140181707237248 [Note] Plugin 'FEEDBACK' is disabled.
2018-05-14 11:14:13 140181707237248 [Note] Server socket created on IP: '127.0.0.1'.
2018-05-14 11:14:13 140181707237248 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '10.1.32-MariaDB'  socket: '/usr/local/mysql/data/mysql.sock'  port: 3306  MariaDB Server


[B]2018-05-14 11:15:33 140181681822464 [Note] /usr/local/mysql/bin/mysqld: Normal shutdown[/B]
2018-05-14 11:15:33 140181681822464 [Note] Event Scheduler: Purging the queue. 0 events
2018-05-14 11:15:34 140181021644544 [Note] InnoDB: FTS optimize thread exiting.
2018-05-14 11:15:34 140181681822464 [Note] InnoDB: Starting shutdown...
2018-05-14 11:15:35 140181681822464 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-05-14 11:15:37 140181681822464 [Note] InnoDB: Shutdown completed; log sequence number 190263381455
2018-05-14 11:15:37 140181681822464 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

180514 11:15:37 mysqld_safe mysqld from pid file /usr/local/mysql/data/mysqld.pid ended
180514 11:17:05 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2018-05-14 11:17:05 140363964790656 [Note] /usr/local/mysql/bin/mysqld (mysqld 10.1.33-MariaDB) starting as process 20018 ...
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

2018-05-14 11:17:05 140363964790656 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: The InnoDB memory heap is disabled
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: Using Linux native AIO
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: Using generic crc32 instructions
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: Completed initialization of buffer pool
2018-05-14 11:17:05 140363964790656 [Note] InnoDB: Highest supported file format is Barracuda.
2018-05-14 11:17:26 140363964790656 [Note] InnoDB: 128 rollback segment(s) are active.
2018-05-14 11:17:26 140363964790656 [Note] InnoDB: Waiting for purge to start
2018-05-14 11:17:26 140363964790656 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.39-83.1 started; log sequence number 190263381455
2018-05-14 11:17:26 140363226412800 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-05-14 11:17:26 140363964790656 [Note] Plugin 'FEEDBACK' is disabled.
2018-05-14 11:17:26 140363964790656 [Note] Server socket created on IP: '127.0.0.1'.
2018-05-14 11:17:26 140363964259072 [Note] /usr/local/mysql/bin/mysqld: Normal shutdown
2018-05-14 11:17:26 140363964790656 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '10.1.33-MariaDB'  socket: '/usr/local/mysql/data/mysql.sock'  port: 3306  MariaDB Server
2018-05-14 11:17:26 140363964259072 [Note] Event Scheduler: Purging the queue. 0 events
2018-05-14 11:17:26 140363276736256 [Note] InnoDB: FTS optimize thread exiting.
2018-05-14 11:17:26 140363964259072 [Note] InnoDB: Starting shutdown...
2018-05-14 11:17:27 140363964259072 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-05-14 11:17:29 140363964259072 [Note] InnoDB: Shutdown completed; log sequence number 190263381465
2018-05-14 11:17:29 140363964259072 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

180514 11:17:29 mysqld_safe mysqld from pid file /usr/local/mysql/data/mysqld.pid ended
180514 11:17:29 mysqld_safe Starting mysqld daemon with databases from /usr/local/mysql/data
2018-05-14 11:17:29 140071314880384 [Note] /usr/local/mysql/bin/mysqld (mysqld 10.1.33-MariaDB) starting as process 20198 ...
2018-05-14 11:17:29 140071314880384 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: The InnoDB memory heap is disabled
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Using Linux native AIO
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Using generic crc32 instructions
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Completed initialization of buffer pool
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Highest supported file format is Barracuda.
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: 128 rollback segment(s) are active.
2018-05-14 11:17:30 140071314880384 [Note] InnoDB: Waiting for purge to start
2018-05-14 11:17:30 140071314880384 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.39-83.1 started; log sequence number 190263381465
2018-05-14 11:17:30 140070585624320 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-05-14 11:17:30 140071314880384 [Note] Plugin 'FEEDBACK' is disabled.
2018-05-14 11:17:30 140071314880384 [Note] Server socket created on IP: '127.0.0.1'.
2018-05-14 11:17:30 140071314880384 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '10.1.33-MariaDB'  socket: '/usr/local/mysql/data/mysql.sock'  port: 3306  MariaDB Server
 
Hi Alex,

Thanks for your reply. I've just tried that: does not work.

The issue is somewhere between "Highest supported file format is Barracuda" and "128 rollback segment(s) are active" (on times 2018-05-14 11:17:05 and 2018-05-14 11:17:26). I'm not sure what happens there but it takes about 20 seconds and the build script does not wait that long...

I see in my original post it took about 9 seconds, so this is increasing?
 
Last edited:
Try this - stop httpd and then try the restart. If the restart is fast, then it may be related to a php process which opens connection, does not close it and executes for very long time. Therefore the connection is stalling and waiting for the max execution time to end...

You can also check for such processes by logging in to the mysql/mariadb shell and execute SHOW PROCESSLIST.

Just a guess.
 
Hi all,

With the last update from MariaDB 10.1.34 to 10.1.35 the issue was gone!

Two things have changed:
1. The build script is updated, but I'm not sure if there are relevant changes for this in there
2. I've removed a very large database. I had a Piwik (now Matomo) installation resulting in a 450+ mb database file (uncompressed export). I can imagine a large database could slow down the start of Mariadb?
 
It definitely can, especially if there are large transactions working on it, so lots of locks and rollbacks...
 
Back
Top