На днях у моего коллеги и моего друга, Питера Бороса, был случай, когда одному из наших клиентов пришлось отслеживать процесс закрытия MySQL. Этот блог основан на нашем внутреннем обсуждении.
Наш клиент хотел, чтобы Питер выявил виновника периодических отключений. Это оказалось немного сложнее, чем обычно, по причинам, которые вы можете догадаться из названия этого блога.
Вот что увидел Питер в логах:
150928 15:15:33 [Note] /usr/sbin/mysqld: Normal shutdown
150928 15:15:36 [Note] Event Scheduler: Purging the queue. 0 events
150928 15:15:39 [Warning] /usr/sbin/mysqld: Forcing close of thread 411515 user: 'dashboard'
150928 15:15:40 InnoDB: Starting shutdown...
150928 15:15:59 InnoDB: Shutdown completed; log sequence number 4873840375
150928 15:16:00 [Note] /usr/sbin/mysqld: Shutdown completeНекоторые из вас могут вспомнить, что я написал сообщение в блоге об инструментах, которые могут помочь вам идентифицировать другие процессы, отправляющие сигналы в mysqld. Питер выбрал SystemTap для отслеживания процесса. Сценарий, который он использовал для отслеживания, был из блога Дэвида Басби :
probe signal.send {
if (sig_name == "SIGKILL" || sig_name == "SIGTERM")
printf("[%s] %s was sent to %s (pid:%d) by %s uid:%dn",
ctime(gettimeofday_s()),
sig_name,
pid_name,
sig_pid,
execname(),
uid()
)
}Используя этот скрипт SystemTap, Питер обнаружил, что «убийцей» был mysqld:
[Wed Sep 16 18:57:33 2015] SIGTERM was sent to mysqld (pid:31191) by mysqld uid:497
[Wed Sep 16 18:57:34 2015] SIGTERM was sent to mysqld (pid:31191) by mysqld uid:497
[Wed Sep 16 18:57:34 2015] SIGTERM was sent to mysqld (pid:31191) by mysqld uid:497
[Wed Sep 16 18:57:40 2015] SIGTERM was sent to mysqld (pid:31191) by mysqld uid:497
[Mon Sep 28 15:15:31 2015] SIGTERM was sent to mysqld (pid:12203) by mysqld uid:497
[Mon Sep 28 15:15:31 2015] SIGTERM was sent to mysqld (pid:12203) by mysqld uid:497
[Mon Sep 28 15:16:00 2015] SIGTERM was sent to mysqld (pid:12203) by mysqld uid:497Как вы можете видеть выше, mysqld получил SIGTERM от mysqld. Как это возможно? Давайте попробуем истолковать то, что здесь произошло!
Согласно инструкции , отключение сервера может быть инициировано разными способами. Например:
- SIGTERM отправляется в mysqld пользователем UNIX
- сервер отключен в административном порядке с помощью
mysqladmin shutdownпривилегированного пользователя MySQL
Давайте предположим, что речь идет о первом примере, где привилегированный процесс / скрипт отправляет SIGTERM в mysqld. Если бы это было так, мы бы получили:
[root@centos7 ~]# kill -15 `pidof -x mysqld`
[root@centos7 ~]#[root@centos7 ~]# ./signals.stp
[Thu Oct 1 17:56:36 2015] SIGTERM was sent to mysqld (pid:2105) by bash uid:0
[Thu Oct 1 17:56:37 2015] SIGTERM was sent to mysqld (pid:2105) by mysqld uid:995Первая строка в вышеприведенном выводе показывает клиентский процесс (bash), который выдал сигнал TERM для MySQL. В ответ MySQL запустил поток обработчика сигналов и обработал завершение ( COM_SHUTDOWN ), используя этот поток. В свою очередь указанная функция kill_mysqld () может отправить сигнал current_pid от имени инициирующего процесса.
Как примечание: в приведенном выше выводе вы не видите ничего, связанного с потоками. Вы могли бы получить еще больше подробностей о работе MySQL, если бы изменили код tapscript, включив в него системные вызовы tgkill и также отобразив идентификаторы связанных потоков:
#!/usr/bin/env stap
probe signal.send, signal.systgkill {
if (sig_name == "SIGKILL" || sig_name == "SIGTERM")
printf("[%s] %s was sent to %s (pid:%d) by %s (pid: %d, tid:%d) uid:%dn",
ctime(gettimeofday_s()),
sig_name,
pid_name,
sig_pid,
execname(),
pid(),
tid(),
uid()
)
}Хотя это может быть полезно для лучшего понимания того, как ведет себя mysqld, это не имеет значения в нашем поиске виновного, поэтому я не собираюсь включать здесь вывод этого сценария — это упражнение будет оставлено вам, дорогой читатель!
Что произойдет, если пользователь MySQL с правами администратора вместо этого инициирует отключение через консоль? Мы получаем:
[root@centos7 ~]# mysqladmin shutdown
[root@centos7 ~]#[root@centos7 ~]# ./signals.stp
[Thu Oct 1 17:59:08 2015] SIGTERM was sent to mysqld (pid:3906) by mysqld uid:995
[Thu Oct 1 17:59:10 2015] SIGTERM was sent to mysqld (pid:3906) by mysqld uid:995Вы видите, что на этот раз отправителем был mysqld, что полностью напоминает первоначальный вывод, который имел Питер. Таким образом, теперь мы знаем, что мы искали программу под названием mysqladmin shutdown!
К сожалению, это означает, что программа может быть не локальной, и клиент может подключиться с другого хоста. Локальный рекурсивный grep может или не может решить нашу проблему. Однако если мы включим general-log с log-warnings = 2, это может привести к чему-то вроде:
[root@centos7 ~]# tail -F /var/log/mysqld_generic.log
151001 17:07:57 5 Connect robert@192.168.3.101 on
5 ShutdownТаким образом, теперь мы знаем, где запустить наш рекурсивный grep для этого мошеннического mysqladmin shutdown(или аналогичного процесса с использованием API)! В моем случае он работал на удаленном хосте 192.168.3.1 и был подключен как пользователь MySQL ‘robert’.
Конечно, вы можете найти альтернативные методы для отслеживания соединений MySQL, но это выходит за рамки того, что я намеревался включить в этот блог. Возможно в следующем?
Роберт присоединился к американской консалтинговой команде Percona в 2014 году. Он является страстным поклонником OpenSource и всех IT. До прихода в Percona он работал на различных должностях в производственной компании Fortune 500, совсем недавно — архитектором / инженером инфраструктуры. Он родом из Европы, Венгрии, где он был инструктором и преподавал различные классы Sun Microsystems по всей Европе. Роберт имеет некоторое академическое образование, и он управлял сетевыми услугами своего старого Департамента и своего Общежития. В те редкие часы, когда он не за компьютером, он проводит время со своей семьей или играет со своим радиоуправлением.