How to debug MySQL and MariaDB: Difference between revisions

Latest revision as of 09:27, 19 March 2021

There are several ways and levels to debug MariaDB or MySQL server.

I will go from the most common and easy ways anyone can do, to the styles for which you first need a debug build of the server.

User level debugging

In case you are just a common user, and you are trying to make your setup running, or you are e.g. reporting a bug, theese are some things you can do:

1) Check the service

The systemd service for MariaDB is called 'mariadb' and for MySQL it's called 'mysqld'. The systemd service files are located in "/usr/lib/systemd/system/".

The correct way to make changes to them is to create a file with the same name in the "/etc/systemd/system/" directory. Files here override the same named files from the "/usr/lib/systemd/system/".

If you begin the file with line containing ".include /usr/lib/systemd/system/<service_name>.service", it will include the requested file and you can change only the bit you need.

Example of correctly started service:

# systemctl status mariadb
● mariadb.service - MariaDB 10.3 database server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; disabled; vendor preset: disabled)
  Drop-In: /usr/lib/systemd/system/mariadb.service.d
           └─tokudb.conf
   Active: active (running) since Wed 2019-08-28 08:10:46 EDT; 13s ago
     Docs: man:mysqld(8)
           https://mariadb.com/kb/en/library/systemd/
  Process: 4957 ExecStartPre=/usr/libexec/mysql-check-socket (code=exited, status=0/SUCCESS)
  Process: 4979 ExecStartPre=/usr/libexec/mysql-prepare-db-dir mariadb.service (code=exited, status=0/SUCCESS)
  Process: 5191 ExecStartPost=/usr/libexec/mysql-check-upgrade (code=exited, status=0/SUCCESS)
 Main PID: 5112 (mysqld)
   Status: "Taking your SQL requests now..."
    Tasks: 48
   Memory: 144.8M
      CPU: 1.085s
   CGroup: /system.slice/mariadb.service
           └─5112 /usr/libexec/mysqld --basedir=/usr

Aug 28 08:10:46 host-10-0-137-246 mysql-prepare-db-dir[4979]: MySQL manual for more instructions.
Aug 28 08:10:46 host-10-0-137-246 mysql-prepare-db-dir[4979]: Please report any problems at http://mariadb.org/jira
Aug 28 08:10:46 host-10-0-137-246 mysql-prepare-db-dir[4979]: The latest information about MariaDB is available at http://mariadb.org/.
Aug 28 08:10:46 host-10-0-137-246 mysql-prepare-db-dir[4979]: You can find additional information about the MySQL part at:
Aug 28 08:10:46 host-10-0-137-246 mysql-prepare-db-dir[4979]: http://dev.mysql.com
Aug 28 08:10:46 host-10-0-137-246 mysql-prepare-db-dir[4979]: Consider joining MariaDB's strong and vibrant community:
Aug 28 08:10:46 host-10-0-137-246 mysql-prepare-db-dir[4979]: https://mariadb.org/get-involved/
Aug 28 08:10:46 host-10-0-137-246 systemd[1]: Started MariaDB 10.3 database server.

Example of failed service:

# systemctl status mariadb
● mariadb.service - MariaDB 10.4 database server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; disabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Wed 2019-08-28 08:28:33 EDT; 1min 9s ago
     Docs: man:mysqld(8)
           https://mariadb.com/kb/en/library/systemd/
  Process: 18802 ExecStartPre=/usr/libexec/mysql-check-socket (code=exited, status=0/SUCCESS)
  Process: 18824 ExecStartPre=/usr/libexec/mysql-prepare-db-dir mariadb.service (code=exited, status=0/SUCCESS)
  Process: 18859 ExecStart=/usr/libexec/mysqld --basedir=/usr $MYSQLD_OPTS $_WSREP_NEW_CLUSTER (code=exited, status=1/FAILURE)
 Main PID: 18859 (code=exited, status=1/FAILURE)
   Status: "MariaDB server is down"

Aug 28 08:28:32 host-10-0-136-172 systemd[1]: Starting MariaDB 10.4 database server...
Aug 28 08:28:32 host-10-0-136-172 mysql-prepare-db-dir[18824]: Database MariaDB is probably initialized in /var/lib/mysql already, nothing is done.
Aug 28 08:28:32 host-10-0-136-172 mysql-prepare-db-dir[18824]: If this is not the case, make sure the /var/lib/mysql is empty before running mysql-prepare-db-dir.
Aug 28 08:28:32 host-10-0-136-172 mysqld[18859]: 2019-08-28  8:28:32 0 [Note] /usr/libexec/mysqld (mysqld 10.4.6-MariaDB) starting as process 18859 ...
Aug 28 08:28:33 host-10-0-136-172 systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
Aug 28 08:28:33 host-10-0-136-172 systemd[1]: mariadb.service: Failed with result 'exit-code'.
Aug 28 08:28:33 host-10-0-136-172 systemd[1]: Failed to start MariaDB 10.4 database server.

As you can see, this command will also show some lines from the systemd journal.

2) Check the systemd journal

Use 'journalctl' command with option '-u <service_name>' to print all journal messages only for the specified service:

# journalctl -xe -u mariadb
-- Logs begin at Wed 2019-05-22 08:05:22 EDT, end at Wed 2019-08-28 08:28:33 EDT. --
Aug 28 08:28:32 host-10-0-136-172 systemd[1]: Starting MariaDB 10.4 database server...
-- Subject: A start job for unit mariadb.service has begun execution
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- A start job for unit mariadb.service has begun execution.
-- 
-- The job identifier is 1395.
Aug 28 08:28:32 host-10-0-136-172 mysql-prepare-db-dir[18824]: Database MariaDB is probably initialized in /var/lib/mysql already, nothing is done.
Aug 28 08:28:32 host-10-0-136-172 mysql-prepare-db-dir[18824]: If this is not the case, make sure the /var/lib/mysql is empty before running mysql-prepare-db-dir.
Aug 28 08:28:32 host-10-0-136-172 mysqld[18859]: 2019-08-28  8:28:32 0 [Note] /usr/libexec/mysqld (mysqld 10.4.6-MariaDB) starting as process 18859 ...
Aug 28 08:28:33 host-10-0-136-172 systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
-- Subject: Unit process exited
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- An ExecStart= process belonging to unit mariadb.service has exited.
-- 
-- The process' exit code is 'exited' and its exit status is 1.
Aug 28 08:28:33 host-10-0-136-172 systemd[1]: mariadb.service: Failed with result 'exit-code'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- The unit mariadb.service has entered the 'failed' state with result 'exit-code'.
Aug 28 08:28:33 host-10-0-136-172 systemd[1]: Failed to start MariaDB 10.4 database server.
-- Subject: A start job for unit mariadb.service has failed
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- A start job for unit mariadb.service has finished with a failure.
-- 
-- The job identifier is 1395 and the job result is failed.

As you can see, the journal wasn't much helpful.

If the service will successfuly start the daemon atleast to the state it can write to it's logfile, you will find it's messages there.

3) Check the daemon log file

The logfile of MariaDB is "/var/log/mariadb/mariadb.log" and for MySQL "/var/log/mysql/mysqld.log"

# cat /var/log/mariadb/mariadb.log
2019-08-28  8:28:32 0 [Note] InnoDB: Using Linux native AIO
2019-08-28  8:28:32 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-08-28  8:28:32 0 [Note] InnoDB: Uses event mutexes
2019-08-28  8:28:32 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-08-28  8:28:32 0 [Note] InnoDB: Number of pools: 1
2019-08-28  8:28:32 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-08-28  8:28:32 0 [Note] mysqld: O_TMPFILE is not supported on /var/tmp (disabling future attempts)
2019-08-28  8:28:32 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2019-08-28  8:28:32 0 [Note] InnoDB: Completed initialization of buffer pool
2019-08-28  8:28:32 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-08-28  8:28:32 0 [ERROR] InnoDB: Invalid flags 0x4800 in ./ibdata1
2019-08-28  8:28:32 0 [ERROR] InnoDB: Plugin initialization aborted with error Data structure corruption
2019-08-28  8:28:32 0 [Note] InnoDB: Starting shutdown...
2019-08-28  8:28:33 0 [ERROR] Plugin 'InnoDB' init function returned error.
2019-08-28  8:28:33 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2019-08-28  8:28:33 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-08-28  8:28:33 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2019-08-28  8:28:33 0 [ERROR] Unknown/unsupported storage engine: InnoDB
2019-08-28  8:28:33 0 [ERROR] Aborting

There you can clearly see the problem.

Majority of the issues are easy to understand from the daemon log.

4) Check the configuration

Many of the users problems are caused by bad configuration.

The configuration files are "/etc/my.cnf" and inside directory "/etc/my.cnf.d/". Again, it is recomended to create your custom files in that directory, which will overried the default configuration, rather than edit the default configuration directly.

When you are debugging your issues, try to disable most of what you don't actually use (e.g. different storage engines or some server plugins like gssapi etc.)

You can always check your configuration by running:

# /usr/libexec/mysqld --print-defaults
/usr/libexec/mysqld would have been started with the following arguments:
--datadir=/var/lib/mysql --socket=/var/lib/mysql/mysql.sock --log-error=/var/log/mariadb/mariadb.log --pid-file=/run/mariadb/mariadb.pid

which will show you the configuration that will be actually applied by the server.

If you don't see your desired configuration here, you need to fix your configuration.

That's all for now from the user level debugging.

Set maximum verbosity for the Error log

Use "log_warnings" option to configure verbosity of the Error log.
"1" is minimum, "9" is maximum.

[mariadb]
log_warnings=9

https://mariadb.com/kb/en/error-log/

General tips and upstream documentation

Some general tips how to debug the daemon itself (some info valid for Oracle's MySQL only):

For MariaDB specific info, see:

Where to report bugs for MariaDB and MySQL
Bugs for MariaDB (except those that are caused by packaging issue) should be reported to MariaDB upstream. Oracle does not pay that much attention to bugs reported to their bug tracker, but ideally the bugs should be reported there as well.

How to build MariaDB with debugging enabled

First you need to build MariaDB with debug mode enabled. To do so, use the following cmake option during build:

-DCMAKE_BUILD_TYPE=Debug

Do not forget to install -debuginfo package.
You may either install it directly by yum install mariadb-debuginfo or install it with all dependencies using debuginfo-install mariadb

How to configure mysqld daemon

Some useful arguments to /usr/libexec/mysqld:

--skip-stack-trace --gdb --core-file --general-log --general-log-file --verbose

If compiled with debug option, then run with:

--debug

Doc for those and others is available at http://dev.mysql.com/doc/refman/5.5/en/server-system-variables.html.

To set some debugging options for mysqld, create a new configuration file that is read in the end of /etc/my.cnf:

# cat /etc/my.cnf.d/debug.cnf 
[mysqld]
debug=d,info,error,query:o,/tmp/mysqld.trace
stack-trace
core-file

[mysqld_safe]
core-file-size=unlimited

The configuration above instructs mysqld daemon to store full trace file, which may include important information for debugging the daemon. Providing that trace file to upstream may help a lot.

Where the trace file is actually stored
Please, mind, that path /tmp/mysqld.trace is set from the POV of the mysqld process. Service mariadb uses PrivateTmp feature of the systemd, so the log can be found at /tmp/systemd-mariadb.service-XXXXXX/tmp/mysqld.trace actually.

In order to change core file limit for the service started by systemd, create a drop-in configuration file for the service:

# cat /etc/systemd/system/mariadb.service.d/debug.conf
[Service]
LimitCORE=infinity

Where is the core dump stored
After crashing, a core dump is usually located in the datadir, which is /var/lib/mysql in default configuration.

Running mysqld without systemd

It is not very handy to debug daemon run by systemd, which runs mysqld_safe bash script and this script runs mysqld daemon itself. It might be better to run the mysqld daemon directly with the same arguments and under mysql user (so it can work with the data as usually).

#> systemctl start mariadb
#> systemctl status mariadb -l | grep /usr/libexec/mysqld
           └─29233 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --log-error=/var/log/mariadb/mariadb.log --pid-file=/var/run/mariadb/mariadb.pid --socket=/var/lib/mysql/mysql.sock
#> systemctl stop mariadb
#> ulimit -c unlimited
#> su -s /bin/bash mysql -c "/usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --log-error=/var/log/mariadb/mariadb.log --pid-file=/var/run/mariadb/mariadb.pid --socket=/var/lib/mysql/mysql.sock --skip-stack-trace --gdb --core-file --general-log-file=/var/log/mariadb/mariadb_query.log --verbose --general-log=1 &"
#> # play with mysql
#> echo "create table ..." | mysql test
#> # observe the log files /var/log/mariadb/mariadb.log /var/log/mariadb/mariadb_query.log
#> killall mysqld

Also systemtap can be used to debug mysqld.
If somebody is familiar with systemtap and is able to use it to debug MariaDB/MySQL, be so kind and describe it shortly here.

Generating random data

In case you need to populate your tables to run some tests, there is a small handy command line tool from Percona:
Download the tool (GitHub)
Article from Percona on how to use it

Generating Core Dump files

1) Update server configuration

For MariaDB add:

[mariadb] 
core-file

For MySQL add:

[mysqld] 
core-file

2) For MySQL >= 8.0, update the systemd core dump configuration

Change proc/sys/fs/suid_dumpable:

# cat /proc/sys/fs/suid_dumpable
0
# echo 2 > /proc/sys/fs/suid_dumpable
# cat /proc/sys/fs/suid_dumpable
2

3) Start the server, apply the new configuration

IMPORTANT:
Configuration from previous steps won't be applied until next start of the service!

If the server wasn't running, just start it. Otherwise restart the server.

4) Get the core dump

Either wait for one in buggy server, or provoke one by sending SIG 11 to the daemon.

5) Where to find the generated coredump file

coredumpctl utility takes care of coredumps on Fedora by default. It looks something like this:

# coredumpctl
    TIME                            PID   UID   GID SIG COREFILE  EXE
    Tue 2019-02-26 16:08:13 EST    2916    27    27  11 present   /usr/libexec/mysqld

In order to get the coredump file, you need to call

# coredumpctl -o <path> dump <pid>

Where -o <path> is the location where should be the file saved, dump is telling what to do and <pid> is a pattern to match the specific coredump if more are available. In such cases, PID is usually a nice unique indentificator.

The default location for coredumps for both MariaDB and MySQL are in their datadirs (/usr/lib/mysql). If you have coredumpctl disabled for example, you'll find them there.

IMPORTANT:
Please note the size of the core dump. Freshly installed, empty database will produce ~0,5GB coredump. DB with real load can easily produce coredumps of dozens or even hundreds of GB!

Search