Mysql query error log - Исправление ошибок и поиск оптимальных решений проблем

Содержание

Журналы (logs) в MySQL
Бинарный лог
Лог ошибок
Лог медленных запросов
Лог запросов
Лог репликаций
Логирование в MySQL
Лог ошибок
Бинарный (он же двоичный) лог
Лог запросов
Лог медленных запросов
Просмотр логов
Ротация логов
DDL Log
Самое главное
Журналы (logs) в MySQL
Бинарный лог
Лог ошибок
Лог медленных запросов
Лог запросов
Лог репликаций

Журналы (logs) в MySQL

В MySQL на данный момент существуют 4 вида журнала (лога) и при достаточно серьёзной работе с базами на MySQL необходимо за ними следить. Например, бинарный лог у нас за сутки набирает около гигабайта, а размер жёсткого диска на сервере ограничен и за ними надо следить. Однако следить следует не только за бинарным логом, так как логи (журналы) в MySQL могут принести немалую пользу.

Итак, какие логи ведёт MySQL? Это:
1. бинарный лог (binary log)
2. лог ошибок (error log)
3. лог медленный запросов (slow query log)
4. лог запросов (general query log)
5. лог репликаций (relay log)

Каждый из них по-своему полезен.

Бинарный лог

В первую очередь полезен с точки зрения репликаций. Можно его бэкапить, можно использовать для восстановления данных на более точное время при использовании бэкапов. Лог содержит все команды изменений базы данных, выборки (select, show) не сохраняет, для таблиц, поддерживающих транзакции (BDB, InnoDB) запись в лог выполняется только после выполнения команды COMMIT . Для лога можно указывать список баз данных, которые надо логировать и список баз данных, которые не надо логировать. В более ранних версиях вместо бинарного лога использовался лог обновлений. Использование бинарного лога снижает производительность базы данных, однако его польза настолько велика, что крайне не рекомендуется его отключать. Рекомендуется защищать бинарный лог паролем, так как он может данные также о паролях пользователей. При достижении максимально разрешённого размера (1 гиг по умолчанию) создаётся следующий файл. Каждый новый файл имеет порядковый номер после имени.

Содержание бинарного лога можно посмотреть с помощью утилиты mysqlbinlog.

Основные настройки в my.cnf

Местоположение лога:
log_bin = /var/log/mysql/mysql-bin.log

Максимальный размер, минимум 4096 байт, по умолчанию 1073741824 байт (1 гигабайт):
max_binlog_size= 500M

Сколько дней хранится:
expire_logs_days = 3

Наиболее часто использующиеся команды

Повторение действий после операции восстановления:
shell> mysqlbinlog log_file | mysql -h server_name

Удаление логов до определённого файла:
PURGE BINARY LOGS TO ‘mysql-bin.000’;

Удаление логов до определённой даты:
PURGE BINARY LOGS BEFORE ‘YYYY-MM-DD hh:mm:ss’;

Лог ошибок

Особенно полезен в случаях сбоев. Лог содержит информацию об остановках, запусках сервера, а также сообщения о критических ошибках. Может содержать сообщения с предупреждениями (warnings).

Основные настройки в my.cnf

Местоположение лога:
log_error = /var/log/mysql/mysql.err

Флаг, указывающий стоит ли записывать в лог в том числе предупреждения (записываются, если значение больше нуля):
log_warnings = 1

Наиболее часто использующиеся команды

Переход к новому файл лога:
shell> mysqladmin flush-logs

Копирование старой части лога (необходимо, так как в случае повторного выполнения fluch он будет удалён):
shell> mv host_name.err-old backup-directory

Лог медленных запросов

Если есть подозрение, что приложение работает медленно из-за неэффективных запросов к базе, то в первую очередь следует проверить лог медленных запросов. В случае оптимизации запросов этот лог поможет выяснить, что необходимо оптимизировать в первую очередь.

Основные настройки в my.cnf

Местоположение лога:
log_slow_queries = /var/log/mysql/mysql_slow.log

Со скольки секунд выполнения запрос считается медленным, минимальное значений — 1 секунда, по умолчанию 10 секунд:
long_query_time = 10

Если надо логировать запросы, которые не используют индексы, надо добавить строку:
log-queries-not-using-indexes

Если надо вести лог медленных команд, таких как OPTIMIZE TABLE , ANALYZE TABLE и ALTER TABLE :
log-slow-admin-statements

Лог запросов

Лог содержит информацию о подключениях и отключениях клиентов, а также все SQL запросы, которые были получены. Фактически, это временный лог. Обычно лог удаляется автоматически сразу после выполнения всех команд (т.е. как только он стал ненужным). Лог ведётся в соответствии с очередность поступления запросов. Этот лог содержит все запросы к базе данных (независимо от приложений и пользователей). Так что если есть желание (или необходимость) проанализировать, какие необходимы индексы, какие запросы могли бы оптимизированы, то этот лог как раз может помочь в таких целях. Лог полезен не только для случаев, когда необходимо знать, какие запросы выполняются с базой данных, но и в случаях, когда ясно, что возникла ошибка с базой данных, но неизвестно, какой запрос был отправлен к базе данных (например, в случае генерации динамического SQL-а). Рекомендуется защищать лог запросов паролем, так как он может данные также о паролях пользователей.

Основные настройки в my.cnf

Местоположение лога:
log = /var/log/mysql/mysql.log

Наиболее часто использующиеся команды

В отличии от других логов, перезагрузка сервера и команда fluch не инициирует создание нового лога. Но это можно сделать вручную:
shell> mv host_name.log host_name-old.log
shell> mysqladmin flush-logs
shell> mv host_name-old.log backup-directory

Лог репликаций

Здесь логируются изменения, выполненные по инициации сервера репликаций. Как и бинарный лог, состоит из файлов, каждый из которых пронумерован.

Основные настройки в my.cnf

Местоположение лога:
relay-log = /var/log/mysql/mysql-relay-bin.log

Максимальный размер:
max_relay_log_size = 500М

Наиболее часто использующиеся команды

Начать новый файл лога можно только при остановленном дополнительном (slave) сервере:
shell> cat new_relay_log_name.index >> old_relay_log_name.index
shell> mv old_relay_log_name.index new_relay_log_name.index

Команда fluch logs инициирует ротацию лога.

Источник

Логирование в MySQL

Технический редактор Highload

Журналы событий — первый и самый простой инструмент для определения статуса системы и выявления ошибок. Основных логов в MySQL четыре:

Собираем на дрон для штурмовиков Николаевской области. Он поможет найти и уничтожить врага

Error Log — стандартный лог ошибок, которые собираются во время работы сервера (в том числе start и stop);
Binary Log — лог всех команд изменения БД, нужен для репликации и бэкапов;

Лог ошибок

Этот журнал содержит все ошибки, которые произошли во время работы сервера, включая критические ошибки, а также остановки, включения сервера и предупреждения (warnings). С него нужно начать в случае сбоя системы. По умолчанию все ошибки выводятся в консоль (stderr), также можно записывать ошибки в syslog (по умолчанию в Debian) или отдельный лог-файл:

log_error=/var/log/mysql/mysql_error.log
Ошибки будут писаться в mysql_error.log

Рекомендуем держать этот журнал включенным для быстрого определения ошибок. А для понимания, что значит та или иная ошибка, в MySQL присутствует утилита [http://dev.mysql.com/doc/refman/5.7/en/perror.html perror]:

Объясняет значения кодов ошибок

Бинарный (он же двоичный) лог

В бинарный лог записываются все команды изменения базы данных, пригодится для репликации и восстановления.

Указывает расположение, срок жизни и максимальный размер файла

Учтите, что если вы не собираетесь масштабировать систему и реализовывать отказоустойчивость, то бинарный лог лучше не включать. Он требователен к ресурсам и снижает производительность системы.

Лог запросов

В этом журнале содержатся все полученные SQL-запросы, информация о подключениях клиентов. Может пригодиться для анализа индексов и оптимизации, а также выявления ошибочных запросов:

Включает лог и указывает расположение файла

Также его можно включить/отключить во время работы сервера MySQL:

Для применения не нужно перезагружать сервер

Лог медленных запросов

Журнал пригодится для определения медленных, то есть неэффективных запросов. Подробнее читайте в этой статье.

Просмотр логов

Для просмотра логов на Debian (Ubuntu) нужно выполнить:

Если логи не указаны отдельно, то находятся в /var/lib/mysql

Ротация логов

Не забывайте сжимать (архивировать, ротировать) файлы логов, чтобы они занимали меньше места на сервере. Для этого используйте утилиту logrotate, отредактировав файл конфигурации /etc/logrotate.d/mysql-server :

Сжимает и архивирует нужные логи, очищает файлы

DDL Log

MySQL также ведет лог языка описания данных. В него собираются данные операций типа DROP_TABLE and ALTER_TABLE. Лог используется для восстановления после сбоев, которые произошли во время выполнения таких операций. [http://dev.mysql.com/doc/refman/5.7/en/ddl-log.html DDL Log] — бинарный файл, не предназначенный для чтения пользователем, поэтому не модифицируйте и не удаляйте его.

Самое главное

Всегда включайте лог ошибок, используйте лог запросов для проверки соединения приложения с базой данных, проверки запросов и работы memcached. Лог медленных запросов пригодится для оптимизации работы MySQL.

Этот текст был написан несколько лет назад. С тех пор упомянутые здесь инструменты и софт могли получить обновления. Пожалуйста, проверяйте их актуальность.

Источник

Журналы (logs) в MySQL

Каждый из них по-своему полезен.

Бинарный лог

Содержание бинарного лога можно посмотреть с помощью утилиты mysqlbinlog.

Основные настройки в my.cnf

Местоположение лога:
log_bin = /var/log/mysql/mysql-bin.log

Максимальный размер, минимум 4096 байт, по умолчанию 1073741824 байт (1 гигабайт):
max_binlog_size= 500M

Сколько дней хранится:
expire_logs_days = 3

Наиболее часто использующиеся команды

Повторение действий после операции восстановления:
shell> mysqlbinlog log_file | mysql -h server_name

Удаление логов до определённого файла:
PURGE BINARY LOGS TO ‘mysql-bin.000’;

Удаление логов до определённой даты:
PURGE BINARY LOGS BEFORE ‘YYYY-MM-DD hh:mm:ss’;

Лог ошибок

Основные настройки в my.cnf

Местоположение лога:
log_error = /var/log/mysql/mysql.err

Наиболее часто использующиеся команды

Переход к новому файл лога:
shell> mysqladmin flush-logs

Лог медленных запросов

Основные настройки в my.cnf

Местоположение лога:
log_slow_queries = /var/log/mysql/mysql_slow.log

Если надо логировать запросы, которые не используют индексы, надо добавить строку:
log-queries-not-using-indexes

Если надо вести лог медленных команд, таких как OPTIMIZE TABLE , ANALYZE TABLE и ALTER TABLE :
log-slow-admin-statements

Лог запросов

Основные настройки в my.cnf

Местоположение лога:
log = /var/log/mysql/mysql.log

Наиболее часто использующиеся команды

Лог репликаций

Основные настройки в my.cnf

Местоположение лога:
relay-log = /var/log/mysql/mysql-relay-bin.log

Максимальный размер:
max_relay_log_size = 500М

Наиболее часто использующиеся команды

Команда fluch logs инициирует ротацию лога.

Источник

Error Log — стандартный лог ошибок, которые собираются во время работы сервера (в том числе start и stop);
Binary Log — лог всех команд изменения БД, нужен для репликации и бэкапов;
General Query Log — основной лог запросов;
Slow Query Log — лог медленных запросов.

Лог ошибок

log_error=/var/log/mysql/mysql_error.log

Рекомендуем держать этот журнал включенным для быстрого определения ошибок. А для понимания, что значит та или иная ошибка, в MySQL присутствует утилита perror:

shell> perror 13 64

OS error code 13: Permission denied

OS error code 64: Machine is not on the network

Бинарный (он же двоичный) лог

В бинарный лог записываются все команды изменения базы данных, пригодится для репликации и восстановления.

Включается так:

log_bin = /var/log/mysql/mysql-bin.log

expire_logs_days = 5

max_binlog_size = 500M

Лог запросов

general_log_file = /var/log/mysql/mysql.log

general_log = 1

Также его можно включить/отключить во время работы сервера MySQL:

SET GLOBAL general_log = ‘ON‘;

SET GLOBAL general_log = ‘OFF‘;

Лог медленных запросов

Просмотр логов

Для просмотра логов на Debian (Ubuntu) нужно выполнить:

# Лог ошибок

tail -f /var/log/syslog

#Лог запросов

tail -f /var/log/mysql/mysql.log

# Лог медленных запросов

tail -f /var/log/mysql/mysql-slow.log

Ротация логов

# — I put everything in one block and added sharedscripts, so that mysql gets

# flush-logs’d only once.

# Else the binary logs would automatically increase by n times every day.

# — The error log is obsolete, messages go to syslog now.

/var/log/mysql.log /var/log/mysql/mysql.log /var/log/mysql/mysql-slow.log {

daily

rotate 7

missingok

create 640 mysql adm

compress

sharedscripts

postrotate

test -x /usr/bin/mysqladmin || exit 0

# If this fails, check debian.conf!

MYADMIN=«/usr/bin/mysqladmin —defaults-file=/etc/mysql/debian.cnf»

if [ -z «`$MYADMIN ping 2>/dev/null`» ]; then

# Really no mysqld or rather a missing debian-sys-maint user?

# If this occurs and is not an error please report a bug.

#if ps cax | grep -q mysqld; then

if killall -q -s0 -umysql mysqld; then

exit 1

else

$MYADMIN flush-logs

endscript

}

DDL Log

MySQL также ведет лог языка описания данных. В него собираются данные операций типа DROP_TABLE and ALTER_TABLE. Лог используется для восстановления после сбоев, которые произошли во время выполнения таких операций. DDL Log — бинарный файл, не предназначенный для чтения пользователем, поэтому не модифицируйте и не удаляйте его.

Самое главное

https://github.com/midnight47/

Источник

This tutorial shows you how to configure and view different MySQL logs. MySQL is
an open-source relational database based on SQL (Structured Query Language).
MySQL offers various built-in logs. In general, a database is the cornerstone of
almost every backend, and because of that administrators want to log this
service.

MySQL has multiple logs with different purpose. We will focus on following four
logs:

Error log: Records problems encountered starting, running, or stopping
mysqld. This log is stored by default in the /var/log directory. It could
be useful if you want to analyze the server itself.
General query logs: Records every connection established with each client.
This log records everything that client sent to the server. This log is useful
to determine client problems.
Binary logs: Record each event that manipulates data in the database.
These log records operations such as a table creating, modification of schema,
inserting new values, or querying tables. These logs are used to backup and
recover the database.
Slow query log: Record of each query, which execution took too much time.
This log could be useful for the optimisation of slow SQL queries.

In this tutorial, you will do the following actions:

You will install the MySQL server and view default error log.
You will connect to MySQL server, view metadata about general query logs
and view these logs.
You will understand the concept of the MySQL binary logs and where to find
them.
You will enable and configure a slow query log, simulate some slow query
and check this incident in the new log.

🔭 Want to centralize and monitor your MySQL logs?

Head over to Logtail and start ingesting your logs in 5 minutes.

Prerequisites

You will need:

Ubuntu 20.04 distribution including the non-root user with sudo access.
Basic knowledge of SQL languages (understanding of simple select query
statement).

Step 1 — Viewing Error Log

The MySQL server is maintained by the command-line program mysqld. This
program manages access to the MySQL data directory that contains databases and
tables. The problems encountered during mysqld starting, running, or stopping
are stored as a custom log in the directory /var/log/mysql. This log doesn’t
include any information about SQL queries. It is useful for the analysis of the
MySQL server.

First of all, let’s install the MySQL server. Ubuntu 20.04 allows to install the
MySQL from default packages with the apt install (installation requires sudo
privilege):

$ sudo apt update
$ sudo apt install mysql-server

The first command will update Ubuntu repositories, and the second will download
and install required packages for the MySQL server.

Now, the server is installed. The new service already creates a default error
log. You can list the directory /var/log and find a new subdirectory mysql
with ls:

You’ll see the program’s output appear on the screen:

Output
alternatives.log       bootstrap.log           kern.log.4.gz
alternatives.log.1     btmp                    lastlog
alternatives.log.2.gz  btmp.1                  letsencrypt
alternatives.log.3.gz  cups                    my-custom-app
apache2                dist-upgrade            mysql
apport.log             dmesg                   openvpn
apport.log.1           dmesg.0                 private
apport.log.2.gz        dmesg.1.gz              speech-dispatcher
apport.log.3.gz        dmesg.2.gz              syslog
apport.log.4.gz        dmesg.3.gz              syslog.1
apport.log.5.gz        dmesg.4.gz              syslog.2.gz
apport.log.6.gz        dpkg.log                syslog.3.gz
apport.log.7.gz        dpkg.log.1              syslog.4.gz
apt                    dpkg.log.2.gz           syslog.5.gz
auth.log               dpkg.log.3.gz           syslog.6.gz
auth.log.1             faillog                 syslog.7.gz
auth.log.2.gz          fontconfig.log          teamviewer15
auth.log.3.gz          gdm3                    test.log
auth.log.4.gz          gpu-manager.log         ubuntu-advantage.log
boot.log               gpu-manager-switch.log  unattended-upgrades
boot.log.1             hp                      wtmp
boot.log.2             installer               wtmp.1
boot.log.3             journal                 Xorg.0.log
boot.log.4             kern.log                Xorg.0.log.old
boot.log.5             kern.log.1              Xorg.1.log
boot.log.6             kern.log.2.gz           Xorg.1.log.old
boot.log.7             kern.log.3.gz

The output shows also directory mysql. This directory contains by default
single log error.log. Let’s view the content of file error.log with cat:

cat /var/log/mysql/error.log

You’ll see the program’s output appear on the screen:

Output
2021-04-28T09:36:19.040254Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.23-0ubuntu0.20.04.1) initializing of server in progress as process 62373
2021-04-28T09:36:19.046865Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-04-28T09:36:20.482915Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-04-28T09:36:23.709432Z 6 [Warning] [MY-010453] [Server] [email protected] is created with an empty password ! Please consider switching off the --initialize-insecure option.
2021-04-28T09:36:28.971810Z 6 [System] [MY-013172] [Server] Received SHUTDOWN from user boot. Shutting down mysqld (Version: 8.0.23-0ubuntu0.20.04.1).
2021-04-28T09:36:33.851492Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.23-0ubuntu0.20.04.1) starting as process 62437
2021-04-28T09:36:33.870257Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-04-28T09:36:34.114770Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-04-28T09:36:34.222753Z 0 [ERROR] [MY-011292] [Server] Plugin mysqlx reported: 'Preparation of I/O interfaces failed, X Protocol won't be accessible'
2021-04-28T09:36:34.222924Z 0 [ERROR] [MY-011300] [Server] Plugin mysqlx reported: 'Setup of socket: '/var/run/mysqld/mysqlx.sock' failed, can't create lock file /var/run/mysqld/mysqlx.sock.lock'
2021-04-28T09:36:34.354295Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-04-28T09:36:34.354479Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
...

The output shows that the file stores plain text records about the mysqld
server initialisation, and running.

Step 2 — Viewing General Query Logs

The server writes records about each client event during connection to the
general query log. Basically, it keeps the information about all SQL statements
that happens. This log is useful when the administrators want to know what
clients exactly execute.

Connecting to Server and Checking General Query Log Status

First of all, let’s check the status of the general query log because this
logging feature can be turned off.

You can connect to MySQL server as a root client:

You will be redirected to MySQL command-line.

Now, you can view system variables related to the general query log by executing
command show variables:

mysql> show variables like '%general%';

The clause specifies a pattern that should match the variable. In our case, the
pattern '%general%' specifies to show variables that contain the string
general. You’ll see the program’s output appear on the screen:

Output
+------------------+-----------------------------+
| Variable_name    | Value                       |
+------------------+-----------------------------+
| general_log      | ON                          |
| general_log_file | /var/lib/mysql/alice.log    |
+------------------+-----------------------------+
2 rows in set (0.01 sec)

The output shows two variables:

general_log: the variable holds value ON (general log enable), or OFF
(general log disabled).
general_log_file: the variable defines where is the log stored in the file
system.

As you can see, the general query log is by default enabled. We can disconnect
from the server by executing the exit command:

You will be redirected back to the terminal.

Viewing General Query Log

Now, you can view the content of this log with a cat (the sudo is required
because this file is maintained by the system):

$ sudo cat /var/lib/mysql/alice.log

You’ll see the program’s output appear on the screen:

Output
/usr/sbin/mysqld, Version: 8.0.23-0ubuntu0.20.04.1 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
2021-04-28T10:47:28.713271Z    10 Connect   [email protected] on  using Socket
2021-04-28T10:47:28.713625Z    10 Query select @@version_comment limit 1
2021-04-28T10:53:50.778598Z    10 Query show variables like '%general%'
2021-04-28T13:35:41.944309Z    10 Quit

The output shows all statement executed on the server. You can see the time
stamp and the specific command that was executed. There is also the executed
command show variables like '%general%'.

Step 3 — Listing Binary Logs

The binary log contains events that manipulated the database. If you want to
recover the database, you need a backup and a binary log relevant to this
backup. There are multiple binary logs because they are versioned.

By default, the binary logs are enabled. You can check where are they stored.
Let’s connect to the MySQL server as a root client:

You will be redirected to MySQL prompt.

Now, you can check the binary logs status by executing show binary logs:

The command will list the binary log files on the server:

Output
+---------------+-----------+-----------+
| Log_name      | File_size | Encrypted |
+---------------+-----------+-----------+
| binlog.000001 |       179 | No        |
| binlog.000002 |       403 | No        |
| binlog.000003 |       770 | No        |
| binlog.000004 |       179 | No        |
| binlog.000005 |       403 | No        |
| binlog.000006 |       892 | No        |
+---------------+-----------+-----------+
6 rows in set (0.00 sec)

The output shows all binary logs. Now, we can find out where are this logs
stored.

We can show logs location by executing command show variables:

mysql> show variables like '%log_bin%';

We already use this show clause in the previous step. This time, the clause
shows variables that contain the string log_bin. You’ll see the program’s
output appear on the screen:

Output
+---------------------------------+-----------------------------+
| Variable_name                   | Value                       |
+---------------------------------+-----------------------------+
| log_bin                         | ON                          |
| log_bin_basename                | /var/lib/mysql/binlog       |
| log_bin_index                   | /var/lib/mysql/binlog.index |
| log_bin_trust_function_creators | OFF                         |
| log_bin_use_v1_row_events       | OFF                         |
| sql_log_bin                     | ON                          |
+---------------------------------+-----------------------------+
6 rows in set (0.00 sec)

The output shows that the binary logs are stored in directory /var/lib/mysql,
and they are labelled as binlog.index (for example binlog.000001).

We can disconnect from the server by executing the exit command:

You will be redirected back to the terminal.

Now, let’s list the directory /var/lib/mysql but only as a root because it is
owned and maintained by the system:

You’ll see the program’s output appear on the screen:

Output
auto.cnf         ca.pem                 ib_logfile0    private_key.pem
binlog.000001    client-cert.pem      ib_logfile1      public_key.pem
binlog.000002    client-key.pem       ibtmp1             server-cert.pem
binlog.000003    debian-5.7.flag      '#innodb_temp' server-key.pem
binlog.000004    EXAMPLE_DB           alice.log      sys
binlog.000005    '#ib_16384_0.dblwr'  alice.pid      undo_001
binlog.000006    '#ib_16384_1.dblwr'  mysql            undo_002
binlog.index     ib_buffer_pool       mysql.ibd
ca-key.pem     ibdata1              performance_schema

The output shows that the directory /var/lib/mysql contains the binary log
files.

Step 4 — Configuring Slow Query Log

MySQL allows to log queries, which took too much time. This mechanism is called
a slow query log.

Enabling Slow Query Logging

By default, the slow query log is disabled. You can enable it by editing MySQL
configuration file /etc/mysql/mysql.conf.d/mysqld.cnf (sudo required):

$ sudo nano /etc/mysql/mysql.conf.d/mysqld.cnf

The file contains following lines that holds configuration variables (by default
commented out):

...
# Here you can see queries with especially long duration
# slow_query_log          = 1
# slow_query_log_file     = /var/log/mysql/mysql-slow.log
# long_query_time = 10
...

These three lines holds following three configuration variables:

slow_query_log: the slow query logging is disable (value 0) or enabled
(value 1).
slow_query_log_file: the slow query log is stored in the file
/var/log/mysql/mysql-slow.log. You can specify your own file.
long_query_time: by default, the slow query logs record each SQL query that
takes more than 10 seconds. You can change this minimal time interval to
another value. The value can be specified as a floating-point number where the
value 1.0 refers to 1 second.

You can enable slow query log by uncommenting this three lines. Also, you can
set your own long_query_time value:

...
# Here you can see queries with especially long duration
slow_query_log          = 1
slow_query_log_file     = /var/log/mysql/mysql-slow.log
long_query_time = 5
...

In our example, we change the default long_query_time value to 5 seconds. Now,
you can save the file.

If you want immediately apply the new configuration rules then you must restart
the MySQL server with systemctl (sudo required):

$ sudo systemctl restart mysql.service

Now, the MySQL server enables slow query log.

Checking Slow Query Log Status

You can check that the log is enabled if you login into the MySQL server as a
root client:

You will be redirected to MySQL prompt.

Let’s check the slow query log status by executing command show variables:

mysql> show variables like '%slow_query_log%';

Once again, we use the show clause. This time, the clause shows variables that
contain the string slow_query_log. You’ll see the program’s output appear on
the screen:

Output
+---------------------+----------------------------------+
| Variable_name       | Value                            |
+---------------------+----------------------------------+
| slow_query_log      | ON                               |
| slow_query_log_file | /var/log/mysql/mysql-slow.log   |
+---------------------+----------------------------------+
2 rows in set (0.00 sec)

The output shows that the slow query log is enabled (the variable
slow_query_log holds the value ON). The log is stored in the file
/var/log/mysql/mysql-slow.log. You can see that it is the same file as the
file specified in the configuration script.

Let’s view actual slow query time interval by executing the command
show variables:

mysql> show variables like '%long_query_time%';

You’ll see the program’s output appear on the screen:

Output
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time |  5.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

The output shows that the variable long_query_time holds the value 5 seconds
(as we define in the configuration script).

Viewing Slow Query Log

At last, we can check that the MySQL records slow queries to the new log. You
can execute the following select query that takes 6 seconds:

The select will wait 6 seconds and then return 0:

Output
+----------+
| sleep(6) |
+----------+
|        0 |
+----------+
1 row in set (6.01 sec)

The output shows that this query takes 6 seconds. As a result, it should be
recorded in a slow query log.

We can disconnect from the server by executing the exit command:

You will be redirected back to the terminal.

At last, we can print content of the slow query log
/var/log/mysql/mysql-slow.log (the sudo is required because the file is
maintained by system):

$ sudo cat /var/log/mysql/mysql-slow.log

You’ll see the program’s output appear on the screen:

/usr/sbin/mysqld, Version: 8.0.23-0ubuntu0.20.04.1 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2021-04-29T06:28:55.445053Z
# [email protected]: root[root] @ localhost []  Id:    15
# Query_time: 6.000443  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1619677729;
select sleep(6);

You can see that the output shows record about execution query
select sleep(6).

Conclusion

In this tutorial, you configured and viewed different MySQL logs. You installed
the MySQL server and viewed the error log. You connected to the server,
viewed the general query logs and their configuration. You listed binary
logs. At last, you enabled, configured and viewed a slow query log.

Centralize all your logs into one place.

Analyze, correlate and filter logs with SQL.

Create actionable

dashboards.

Share and comment with built-in collaboration.

Got an article suggestion?
Let us know

How To Start Logging With PostgreSQL

Learn how to start logging with PostgreSQL and go from basics to best practices in no time.

→

This work is licensed under a Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License.

Источник

We are yet to see a software that runs perfectly, without any issues. MySQL is no exception there. It’s not the software’s fault – we need to be clear about that. We use MySQL in different places, on different hardware and within different environments. It’s also highly configurable. All those features make it great product but they come with a price – sometimes some settings won’t work correctly under certain conditions. It is also pretty easy to make simple human mistakes like typos in the MySQL configuration. Luckily, MySQL provides us with means to understand what is wrong through the error log. In this blog, we’ll see how to read the information in the error log.

This is the fifteenth installment in the ‘Become a MySQL DBA’ blog series. Our previous posts in the DBA series include:

Optimizing Hints for faster queries,
Using EXPLAIN to improve SQL Queries,
Database Indexing,
Deep Dive pt-query-digest,
Analyzing SQL Workload with pt-query-digest,
Query Tuning Process,
Configuration Tuning,
Live Migration using MySQL Replication,
Database Upgrades,
Replication Topology Changes,
Schema Changes,
High Availability,
Backup & Restore,
Monitoring & Trending.

Error log on MySQL – clean startup and shutdown

MySQL’s error log may contain a lot of information about different issues you may encounter. Let’s start with checking what a ‘clean’ start of MySQL looks like. It will make it easier to find any anomalies later.

At first, all plugins (and storage engines, which do work as plugins in MySQL 5.6) are initiated. If something is not right, you’ll see errors on this stage.

2015-10-26 19:35:20 13762 [Note] Plugin 'FEDERATED' is disabled.

Next we can see a significant part related to InnoDB initialization.

2015-10-26 19:35:20 13762 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-26 19:35:20 13762 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-26 19:35:20 13762 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-26 19:35:20 13762 [Note] InnoDB: Memory barrier is not used
2015-10-26 19:35:20 13762 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-26 19:35:20 13762 [Note] InnoDB: Using Linux native AIO
2015-10-26 19:35:20 13762 [Note] InnoDB: Using CPU crc32 instructions
2015-10-26 19:35:20 13762 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2015-10-26 19:35:21 13762 [Note] InnoDB: Completed initialization of buffer pool
2015-10-26 19:35:21 13762 [Note] InnoDB: Highest supported file format is Barracuda.
2015-10-26 19:35:21 13762 [Note] InnoDB: 128 rollback segment(s) are active.
2015-10-26 19:35:21 13762 [Note] InnoDB: Waiting for purge to start
2015-10-26 19:35:21 13762 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 710963181

In the next phase, authentication plugins are initiated (if they are configured correctly).

2015-10-26 19:35:21 13762 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2015-10-26 19:35:21 13762 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.

At the end you’ll see information about binding MySQL to the configured IP and port. Event scheduler is also initialized. Finally, you’ll see ‘ready for connections’ message indicating that MySQL started correctly.

2015-10-26 19:35:21 13762 [Note] Server hostname (bind-address): '*'; port: 33306
2015-10-26 19:35:21 13762 [Note] IPv6 is available.
2015-10-26 19:35:21 13762 [Note]   - '::' resolves to '::';
2015-10-26 19:35:21 13762 [Note] Server socket created on IP: '::'.
2015-10-26 19:35:21 13762 [Warning] 'proxies_priv' entry '@ [email protected]' ignored in --skip-name-resolve mode.
2015-10-26 19:35:21 13762 [Note] Event Scheduler: Loaded 2 events
2015-10-26 19:35:21 13762 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.26-74.0'  socket: '/var/run/mysqld/mysqld.sock'  port: 33306  Percona Server (GPL), Release 74.0, Revision 32f8dfd

How does the shutdown process look like? Let’s follow it step by step:

2015-10-26 19:35:13 12955 [Note] /usr/sbin/mysqld: Normal shutdown

This line is very important – MySQL can be stopped in many ways – a user can use init scripts, it’s possible to use ‘mysqladmin’ to execute SHUTDOWN command, it’s also possible to send a SIGTERM to MySQL initiating shutdown of the database. At times you’ll be investigating why MySQL instance had stopped – this line is always an indication that someone (or something) triggered clean shutdown. No crash happened, MySQL wasn’t killed either.

2015-10-26 19:35:13 12955 [Note] Giving 12 client threads a chance to die gracefully
2015-10-26 19:35:13 12955 [Note] Event Scheduler: Purging the queue. 2 events
2015-10-26 19:35:13 12955 [Note] Shutting down slave threads
2015-10-26 19:35:15 12955 [Note] Forcefully disconnecting 6 remaining clients
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 37  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 53  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 38  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 39  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 44  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 47  user: 'cmon'

In the above, MySQL is closing remaining connections – it allows them to finish on their own but if they do not close, they will be forcefully terminated.

2015-10-26 19:35:15 12955 [Note] Binlog end
2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'partition'
2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'ARCHIVE'
...

Here MySQL is shutting down all plugins that were enabled in its configuration. There are many of them so we removed some output for the sake of better visibility.

2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'InnoDB'
2015-10-26 19:35:15 12955 [Note] InnoDB: FTS optimize thread exiting.
2015-10-26 19:35:15 12955 [Note] InnoDB: Starting shutdown...
2015-10-26 19:35:17 12955 [Note] InnoDB: Shutdown completed; log sequence number 710963181

One of them is InnoDB – this step may take a while as a clean InnoDB shutdown can take some time on a busy server, even with InnoDB fast shutdown enabled (and this is the default setting).

2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MyISAM'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MRG_MYISAM'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'CSV'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MEMORY'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'sha256_password'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'mysql_old_password'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'mysql_native_password'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'binlog'
2015-10-26 19:35:17 12955 [Note] /usr/sbin/mysqld: Shutdown complete

The shutdown process concludes with ‘Shutdown complete’ message.

Configuration errors

Let’s start with a basic issue – configuration error. It’s really a popular problem. Sometimes we make a typo in a variable name, while editing my.cnf. MySQL parses its configuration files when it starts. If something is wrong, it will refuse to run. Let’s take a look at some examples:

2015-10-27 11:20:05 18858 [Note] Plugin 'FEDERATED' is disabled.
2015-10-27 11:20:05 18858 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-27 11:20:05 18858 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-27 11:20:05 18858 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-27 11:20:05 18858 [Note] InnoDB: Memory barrier is not used
2015-10-27 11:20:05 18858 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-27 11:20:05 18858 [Note] InnoDB: Using Linux native AIO
2015-10-27 11:20:05 18858 [Note] InnoDB: Using CPU crc32 instructions
2015-10-27 11:20:05 18858 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2015-10-27 11:20:05 18858 [Note] InnoDB: Completed initialization of buffer pool
2015-10-27 11:20:05 18858 [Note] InnoDB: Highest supported file format is Barracuda.
2015-10-27 11:20:05 18858 [Note] InnoDB: 128 rollback segment(s) are active.
2015-10-27 11:20:05 18858 [Note] InnoDB: Waiting for purge to start
2015-10-27 11:20:06 18858 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 773268083
2015-10-27 11:20:06 18858 [ERROR] /usr/sbin/mysqld: unknown variable '--max-connections=512'
2015-10-27 11:20:06 18858 [ERROR] Aborting

As you can see from the above, we have here a clear copy-paste error with regards to max_connections variable. MySQL doesn’t accept ‘–’ prefix in my.cnf so if you are copying settings from the ‘ps’ output or from MySQL documentation, please keep it in mind. There are many things that can go wrong but it’s important that ‘unknown variable’ error always points you to my.cnf and to some kind of mistake which MySQL can’t understand.

Another problem can be related to misconfigurations. Let’s say we over-allocated memory on our server. Here’s what you might see:

2015-10-27 11:24:41 31325 [Note] Plugin 'FEDERATED' is disabled.
2015-10-27 11:24:41 31325 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-27 11:24:41 31325 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-27 11:24:41 31325 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-27 11:24:41 31325 [Note] InnoDB: Memory barrier is not used
2015-10-27 11:24:41 31325 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-27 11:24:41 31325 [Note] InnoDB: Using Linux native AIO
2015-10-27 11:24:41 31325 [Note] InnoDB: Using CPU crc32 instructions
2015-10-27 11:24:41 31325 [Note] InnoDB: Initializing buffer pool, size = 512.0G
InnoDB: mmap(70330089472 bytes) failed; errno 12
2015-10-27 11:24:41 31325 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
2015-10-27 11:24:41 31325 [ERROR] Plugin 'InnoDB' init function returned error.
2015-10-27 11:24:41 31325 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-10-27 11:24:41 31325 [ERROR] Unknown/unsupported storage engine: InnoDB
2015-10-27 11:24:41 31325 [ERROR] Aborting

As you can clearly see, we’ve tried to allocate 512G of memory which was not possible on this host. InnoDB is required for MySQL to start, therefore error in initializing InnoDB prevented MySQL from starting.

Permission errors

Below are three examples of three crashes related to permission errors.

/usr/sbin/mysqld: File './binlog.index' not found (Errcode: 13 - Permission denied)
2015-10-27 11:31:40 11469 [ERROR] Aborting

This one is pretty self-explanatory. As stated, MySQL couldn’t find an index file for binary logs due to ‘permission denied’ error. This is also a hard stop for MySQL, it has to be able to read and write to binary logs.

2015-10-27 11:32:46 13601 [Note] Plugin 'FEDERATED' is disabled.
2015-10-27 11:32:46 13601 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-27 11:32:46 13601 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-27 11:32:46 13601 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-27 11:32:46 13601 [Note] InnoDB: Memory barrier is not used
2015-10-27 11:32:46 13601 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-27 11:32:46 13601 [Note] InnoDB: Using Linux native AIO
2015-10-27 11:32:46 13601 [Note] InnoDB: Using CPU crc32 instructions
2015-10-27 11:32:46 13601 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2015-10-27 11:32:46 13601 [Note] InnoDB: Completed initialization of buffer pool
2015-10-27 11:32:46 13601 [ERROR] InnoDB: ./ibdata1 can't be opened in read-write mode
2015-10-27 11:32:46 13601 [ERROR] InnoDB: The system tablespace must be writable!
2015-10-27 11:32:46 13601 [ERROR] Plugin 'InnoDB' init function returned error.
2015-10-27 11:32:46 13601 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-10-27 11:32:46 13601 [ERROR] Unknown/unsupported storage engine: InnoDB
2015-10-27 11:32:46 13601 [ERROR] Aborting

The above is another permission issue, this time the problem is related to ibdata1 file – shared system tablespace which is used for InnoDB to store its internal data (InnoDB dictionary and, by default, undo logs). Even if you use innodb_file_per_table, which is a default setting in MySQL 5.6, InnoDB still requires this file so it can intialize.

2015-10-27 11:35:21 17826 [Note] Plugin 'FEDERATED' is disabled.
/usr/sbin/mysqld: Can't find file: './mysql/plugin.frm' (errno: 13 - Permission denied)
2015-10-27 11:35:21 17826 [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it.
2015-10-27 11:35:21 17826 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-27 11:35:21 17826 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-27 11:35:21 17826 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-27 11:35:21 17826 [Note] InnoDB: Memory barrier is not used
2015-10-27 11:35:21 17826 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-27 11:35:21 17826 [Note] InnoDB: Using Linux native AIO
2015-10-27 11:35:21 17826 [Note] InnoDB: Using CPU crc32 instructions
2015-10-27 11:35:21 17826 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2015-10-27 11:35:21 17826 [Note] InnoDB: Completed initialization of buffer pool
2015-10-27 11:35:21 17826 [Note] InnoDB: Highest supported file format is Barracuda.
2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to
InnoDB: the directory.
2015-10-27 11:35:21 17826 [ERROR] InnoDB: Could not find a valid tablespace file for 'mysql/innodb_index_stats'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
2015-10-27 11:35:21 17826 [ERROR] InnoDB: Tablespace open failed for '"mysql"."innodb_index_stats"', ignored.
2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to
InnoDB: the directory.
2015-10-27 11:35:21 17826 [ERROR] InnoDB: Could not find a valid tablespace file for 'mysql/innodb_table_stats'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
2015-10-27 11:35:21 17826 [ERROR] InnoDB: Tablespace open failed for '"mysql"."innodb_table_stats"', ignored.
2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to
InnoDB: the directory.

Here we have an example of permission issues related to system schema (‘mysql’ schema). As you can see, InnoDB reported it does not have access rights to open tables in this schema. Again, this is serious problem which is a hard stop for MySQL.

Out of memory errors

Another set of frequent issues related to MySQL servers running out of memory. It can manifest in many different ways but the most popular is this one:

Killed
151027 12:18:58 mysqld_safe Number of processes running now: 0

mysqld_safe is an ‘angel’ process which monitors mysqld and restarts it when it dies. It’s true for MySQL but not for recent Galera nodes – in this case it won’t restart MySQL but you’ll see following sequence:

Killed
151027 12:18:58 mysqld_safe Number of processes running now: 0
151027 12:18:58 mysqld_safe WSREP: not restarting wsrep node automatically
151027 12:18:58 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended

Another way memory issue may show up is through the following messages in the error log:

InnoDB: mmap(3145728 bytes) failed; errno 12
InnoDB: mmap(3145728 bytes) failed; errno 12

What’s important to keep in mind is that error codes can easily be checked using ‘perror’ utility. In this case, it makes perfectly clear what exactly happened:

$ perror 12
OS error code  12:  Cannot allocate memory

If you suspect a memory problem or we’d even say – if you are encountering unexpected MySQL crashes, you can also run dmesg to get some more data. If you see output like below, you can be certain that the problem was caused by OOM Killer terminating MySQL:

[ 4165.802544] Out of memory: Kill process 8143 (mysqld) score 938 or sacrifice child
[ 4165.808329] Killed process 8143 (mysqld) total-vm:5101492kB, anon-rss:3789388kB, file-rss:0kB
[ 4166.226410] init: mysql main process (8143) killed by KILL signal
[ 4166.226437] init: mysql main process ended, respawning

InnoDB crashes

InnoDB, most of the time, is a very solid and durable storage engine. Unfortunately, under some circumstances, data may become corrupted. Usually it’s related to either misconfiguration (for example, disabling double-write buffer) or some kind of faulty hardware (faulty memory modules, unstable I/O layer). In those cases it can happen that InnoDB will crash. Crashes can also be triggered by InnoDB bugs. It’s not common but it happens from time to time. No matter the reason of a crash, the error log usually looks in a similar way. Let’s go over a live example.

2015-10-13 15:08:06 7f53f0658700  InnoDB: Assertion failure in thread 139998492198656 in file btr0pcur.cc line 447
InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_block_get_page_no(btr_pcur_get_block(cursor))

InnoDB code is full of sanity checks – assertions are very frequent and, if one of them fails, InnoDB intentionally crashes MySQL. At the beginning you’ll see information about exact location of the assertion which failed. This gives you information about what exactly may have happened – MySQL source code is available on the internet and it’s pretty easy to download code related to your particular version. It may sounds scary but it’s not – MySQL code is properly documented and it’s not a problem to figure out at least what kind of activity triggers your issue.

InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

InnoDB logging tries to be as helpful as possible – as you can see, there’s information about InnoDB recovery process. Under some circumstances it may allow you to start MySQL and dump the InnoDB data. It’s used as “almost a last resort” – one step further and you’ll end up digging in InnoDB files using hex editor.

13:08:06 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=67108864
read_buffer_size=131072
max_used_connections=36
max_threads=514
thread_count=27
connection_count=26
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 269997 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

In the next step you’ll see some of the status counters printed. It’s supposed to give you some idea about configuration – maybe you configured MySQL to use too much resources? Once you go over this data, we’ll reach the backtrace. This piece of information will guide you through the stack and show you what kind of calls were executed when crash happened. Let’s check what exactly happened in this particular case.

Thread pointer: 0xa985960
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f53f0657d40 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8cd37c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x6555a1]
/lib64/libpthread.so.0(+0xf710)[0x7f540f978710]
/lib64/libc.so.6(gsignal+0x35)[0x7f540dfd4625]
/lib64/libc.so.6(abort+0x175)[0x7f540dfd5e05]
/usr/sbin/mysqld[0xa0277b]
/usr/sbin/mysqld[0x567f88]
/usr/sbin/mysqld[0x99afde]
/usr/sbin/mysqld[0x8eb926]
/usr/sbin/mysqld(_ZN7handler11ha_rnd_nextEPh+0x5d)[0x59a6ed]
/usr/sbin/mysqld(_Z13rr_sequentialP11READ_RECORD+0x20)[0x800cd0]
/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyy+0xc88)[0x8128c8]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1bc5)[0x6d6d15]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5a8)[0x6dc228]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x108c)[0x6dda4c]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x162)[0x6ab002]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x6ab0f0]
/usr/sbin/mysqld(pfs_spawn_thread+0x143)[0xaddd73]
/lib64/libpthread.so.0(+0x79d1)[0x7f540f9709d1]
/lib64/libc.so.6(clone+0x6d)[0x7f540e08a8fd]

We can see that problem was triggered when MySQL was executing a DELETE command. Records were read sequentially and full table scan was performed (handler read_rnd_next). Combined with information from the beginning:

InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_block_get_page_no(btr_pcur_get_block(cursor))

we can tell the crash happened when InnoDB was performing a scan of the buffer pool (assertion was triggered in btr_pcur_move_to_next_page method).

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (a991d40): DELETE FROM cmon_stats WHERE cid = 2 AND ts < 1444482484
Connection ID (thread ID): 5
Status: NOT_KILLED

Finally, we can see (sometimes, it’s not always printed) which thread triggered the assertion. In our case we can confirm that indeed it was a DELETE query which caused some kind of problem.

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
151013 15:08:06 mysqld_safe Number of processes running now: 0

As we said, usually MySQL is pretty verbose when it comes to the error log. Sometimes, though, things go so wrong that MySQL can’t really collect much of the information. It still gives a pretty clear indication that something went very wrong (signal 11). Please take a look at the following real life example:

22:31:40 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=10
max_threads=202
thread_count=9
connection_count=7
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 113388 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x1fb7050
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
Segmentation fault (core dumped)
150119 23:48:08 mysqld_safe Number of processes running now: 0

As you can see, we have clear information that MySQL crashed. There’s no additional information, though. Segmentation faults can also be logged in diagnostic messages. In this particular case dmesg returned:

[370591.200799] mysqld[5462]: segfault at 51 ip 00007fe624e3e688 sp 00007fe4f4099c30 error 4 in libgcc_s.so.1[7fe624e2f000+16000]

It’s not much, as you can see, but such information can prove to be very useful if you decide to file a bug against the software provider, be it Oracle, MariaDB, Percona or Codership. It can also be helpful in finding relevant bugs already reported.

It’s not always possible to fix the problem based only on the information written in the error log. It’s definitely a good place to start debugging problems in your database, though. If you are hitting some kind of very common, simple misconfiguration, information you’d find in the error log should be enough to pinpoint a cause and find a solution. If we are talking about serious MySQL crashes, things are definitely different – most likely you won’t be able to fix the issue on your own (unless you are a developer familiar with MySQL code, that is) On the other hand, this data may be more than enough to identify the culprit and locate existing bug reports which cover it. Such bug reports contain lots of discussion and tips or workarounds – it’s likely that you’ll be able to implement one of them. Even information that the given bug was fixed in version x.y.z is useful – you’ll be able to verify it and, if it does solve your problem, to plan for upgrade. In the worst case scenario, you should have enough data to create a bug report on your own.

In the next post in the series, we are going to take a guided tour through the error log (and other logs) you may find in your Galera cluster. We’ll cover what kind of issues you may encounter and how to solve them.

Источник

Over the decades we have been reading the MySQL error log from the server system file, if there are any issues in MySQL or any unknown restart happened , generally we look at the mysql error log.

By default MySQL error log can be found in the default path /var/log/mysqld.log , or it can be explicitly configured using the variable log_error.

Few drawbacks using MySQL error log as FILE

Possibility of missing genuine errors while reading lengthy information.
Filtering of errors for the particular date and timeframes.
Cannot provide the DB server access to developers because of fear of mishandling DB servers.

To overcome the above issues , from MySQL 8.0.22 we can access the error-log from the performance_schema.error_log table.

Granting the SELECT privilege for the error_log table will provide the read access to error log contents using a simple SQL queries for dev teams.

For demo purpose i have installed latest MySQL 8.0.23 in our test environment.

mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.23    |
+-----------+
1 row in set (0.00 sec)

Table structure

mysql> show create table performance_schema.error_logG
*************************** 1. row ***************************
       Table: error_log
Create Table: CREATE TABLE `error_log` (
  `LOGGED` timestamp(6) NOT NULL,
  `THREAD_ID` bigint unsigned DEFAULT NULL,
  `PRIO` enum('System','Error','Warning','Note') NOT NULL,
  `ERROR_CODE` varchar(10) DEFAULT NULL,
  `SUBSYSTEM` varchar(7) DEFAULT NULL,
  `DATA` text NOT NULL,
  PRIMARY KEY (`LOGGED`),
  KEY `THREAD_ID` (`THREAD_ID`),
  KEY `PRIO` (`PRIO`),
  KEY `ERROR_CODE` (`ERROR_CODE`),
  KEY `SUBSYSTEM` (`SUBSYSTEM`)
) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci

Overview to the columns

LOGGED

LOGGED corresponds to the time field of error events occurred , the time values which are stored in the error log table are displayed according to the log_timestamps system variable i.e UTC by default.

we can change the timestamp value by changing log_timestamps variable according to our time zones.

THREAD_ID

It is a MySQL thread ID similar to PROCESSLIST_ID , the thread_id is displayed for events occurred by foreground MySQL threads, for background threads the value be 0.

PRIO

The event priority the permitted values are System, Error, Warning, Note.

ERROR_CODE

Displays the MySQL error codes.

SUBSYSTEM

The subsystem in which the event occurred, example SERVER,INNODB.

DATA

The text representation of the error event.

Variables controlling error logging

Below are the major variables controls the error logging , which defines the output of the error log.

mysql> show global variables like 'log_error%';
+----------------------------+----------------------------------------+
| Variable_name              | Value                                  |
+----------------------------+----------------------------------------+
| log_error                  | /var/log/mysqld.log                    |
| log_error_services         | log_filter_internal; log_sink_internal |
| log_error_suppression_list |                                        |
| log_error_verbosity        | 2                                      |
+----------------------------+----------------------------------------+

log_error – This variable defines the path of the MySQL error log.
log_error_services – This variable controls which log components to enable for error logging ,by default the values are set to log_filter_internal and log_sink_internal.
log_filter_internal: This value provides error log filtering based on the log event priority and error code, in combination with the log_error_verbosity and log_error_suppression_list system variables.
log_sink_internal: This value defines the traditional error log output format.
log_error_suppression_list – This variable helps to filter or ignore the errors, information and warnings which is not worthy or which creates unnecessary noise in the error log.

we can list of one or more comma-separated values indicating the error codes which we need to suppress. Error codes can be specified in symbolic or numeric form.

Example:

Suppose if we insist to filter out the below warning message from error log:

2021-03-26T09:40:40.109075Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.

log_error_suppression_list takes effect based on the log_error_verbosity value defined

mysql> set global log_error_suppression_list='MY-010068';
Query OK, 0 rows affected (0.00 sec)

mysql> show global variables like 'log_error%';
+----------------------------+----------------------------------------+
| Variable_name              | Value                                  |
+----------------------------+----------------------------------------+
| log_error                  | /var/log/mysqld.log                    |
| log_error_services         | log_filter_internal; log_sink_internal |
| log_error_suppression_list | MY-010068                       |
| log_error_verbosity        | 2                                      |
+----------------------------+----------------------------------------+
4 rows in set (0.00 sec)

To persist the value in CNF

[mysqld] 
log_error_verbosity=2 # error and warning messages only #
log_error_suppression_list='MY-010068'

log_error_verbosity

This variables specifies the verbosity of events which will be logged in the error log , permitted values from 1 to 3. default is 2.

log_error_verbosity Value	Permitted Message Priorities
1	`ERROR`
2	`ERROR`, `WARNING`
3	`ERROR`, `WARNING`, `INFORMATION`

Now let us query the performance_schema.error_log table

mysql> SELECT * FROM performance_schema.error_logG
*************************** 1. row ***************************
    LOGGED: 2021-01-18 09:56:33.800985
 THREAD_ID: 0
      PRIO: System
ERROR_CODE: MY-013169
 SUBSYSTEM: Server
      DATA: /usr/sbin/mysqld (mysqld 8.0.23) initializing of server in progress as process 6335
*************************** 2. row ***************************
    LOGGED: 2021-01-18 09:56:33.818823
 THREAD_ID: 1
      PRIO: System
ERROR_CODE: MY-013576
 SUBSYSTEM: InnoDB
      DATA: InnoDB initialization has started.
*************************** 3. row ***************************
    LOGGED: 2021-01-18 09:56:40.454929
 THREAD_ID: 0
      PRIO: System
ERROR_CODE: MY-011323
 SUBSYSTEM: Server
      DATA: X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
*************************** 4. row ***************************
    LOGGED: 2021-02-15 06:00:28.384059
 THREAD_ID: 0
      PRIO: System
ERROR_CODE: MY-013172
 SUBSYSTEM: Server
      DATA: Received SHUTDOWN from user <via user signal>. Shutting down mysqld (Version: 8.0.23).
*************************** 5. row ***************************
    LOGGED: 2021-02-15 06:00:29.583157
 THREAD_ID: 0
      PRIO: System
ERROR_CODE: MY-010910
 SUBSYSTEM: Server
      DATA: /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.23)  MySQL Community Server - GPL.
*************************** 6. row ***************************
    LOGGED: 2021-03-25 06:48:20.350948
 THREAD_ID: 376
      PRIO: Error
ERROR_CODE: MY-012640
 SUBSYSTEM: InnoDB
      DATA: Error number 28 means 'No space left on device'
*************************** 7. row ***************************
    LOGGED: 2021-03-25 06:48:20.416039
 THREAD_ID: 376
      PRIO: Warning
ERROR_CODE: MY-012145
 SUBSYSTEM: InnoDB
      DATA: Error while writing 4194304 zeroes to ./sbtest/sbtest5.ibd starting at offset 1107296256
*************************** 8. row ***************************
    LOGGED: 2021-03-25 06:48:20.434689
 THREAD_ID: 376
      PRIO: Error
ERROR_CODE: MY-013132
 SUBSYSTEM: Server
      DATA: The table 'sbtest5' is full!

with simple SQL queries , we can filter the logs based on priority

mysql> SELECT * FROM performance_schema.error_log WHERE PRIO='error'G
*************************** 1. row ***************************
    LOGGED: 2021-03-26 10:12:42.947343
 THREAD_ID: 0
      PRIO: Error
ERROR_CODE: MY-000067
 SUBSYSTEM: Server
      DATA: unknown variable 'innodb_flush_log_at_trx_t=1'.
*************************** 2. row ***************************
    LOGGED: 2021-03-26 10:12:42.947766
 THREAD_ID: 0
      PRIO: Error
ERROR_CODE: MY-010119
 SUBSYSTEM: Server
      DATA: Aborting

The older events from error_log able are automatically purged when there is a need of space for new events.

The error_log table status can be monitored from SHOW STATUS variables.

mysql> show global status like '%error_log%';
+---------------------------+------------------+
| Variable_name             | Value            |
+---------------------------+------------------+
| Error_log_buffered_bytes  | 8368             |
| Error_log_buffered_events | 62               |
| Error_log_expired_events  | 0                |
| Error_log_latest_write    | 1616753905924032 |
+---------------------------+------------------+
4 rows in set (0.00 sec

Limitations of error_log table

TRUNCATE TABLE is not permitted on error_log table.
The table cannot be index , each column is already indexed by default.

Finally ,introduction of error_log table in MySQL 8 has made error readability more convenient and easy, now the error log can be accessed from remote clients as well with few simple SQL queries without accessing the physical system file.

MySQL error logs table feature benefits the remote connections using MySQL shell and will benefits a lot in DBaaS like AWS RDS , AZURE MySQL , Google Cloud SQL platforms. Where the error log needs a console and log retention is complex.

Published by Waseem Akram

Waseem Akram is an Oracle and AWS certified MySQL DBA. Working in MyDBOPS IT Solutions on MySQL and related technologies to ensures database performance. Handling multi client tasks round the clock and also working with a team of experts at MyDBOPS.
View all posts by Waseem Akram

Published
March 28, 2021March 30, 2021

Источник