The other day a colleague and friend of mine, Peter Boros, had a case where one of our clients had to track down the process shutting down MySQL. This blog is based on the discussion we had about that internally.
Our client wanted Peter to identify the culprit behind periodic shutdowns. This proved to be slightly more difficult than usual, for reasons that you might guess from the title of this blog.
Here is what Peter saw in the logs:
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
Some of you may recall that I wrote a blog post about tools that can help you identify other processes that send signals to mysqld. Peter chose SystemTap to track down the process. The script he used to trace it was from David Busby’s blog:
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()
)
}
Using this SystemTap script Peter discovered that the “killer” was 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
As you can see above, mysqld received a SIGTERM from mysqld. How is this possible? Let’s try to interpret what happened here!
According to the manual, server shutdown can be initiated in different ways. For instance:
- SIGTERM is sent to mysqld by a UNIX user
- server is shut down administratively via
mysqladmin shutdownby a privileged mysql user
Let’s assume that we are talking about the first example, where a privileged process/script sends a SIGTERM to mysqld. If that was the case we would get:
[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
The first line in the above output shows the client process (bash) that issued the TERM signal to MySQL. In response, MySQL started a signal handler thread and processed shutdown (COM_SHUTDOWN) using that thread. In turn the referenced function kill_mysqld() may send a signal to current_pid on behalf of the initiating process.
As a side note, in the above output you don’t see anything related to threads. You could get even more detail about MySQL’s operation if you were to modify the tapscript to include tgkill system calls and display related thread IDs as well:
#!/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()
)
}
While this might be useful to better comprehend how mysqld behaves, it is irrelevant in our search for the culprit process, so I’m not going to include the output of that script here – that exercise will be left to you, dear reader!
Now what happens if a MySQL user with administrative privileges initiates the shutdown via the console instead? We get:
[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
You see that this time the sender was mysqld, which thoroughly resembles the original output that Peter had. Thus, we now know that what we were looking for was a program called mysqladmin shutdown!
Unfortunately, this means that the program may not be local and the client could connect from a different host. A local recursive grep may or may not solve our problem. However, if we enable general-log with log-warnings=2 it might yield something like:
[root@centos7 ~]# tail -F /var/log/mysqld_generic.log 151001 17:07:57 5 Connect robert@192.168.3.101 on 5 Shutdown
Thus, we now know where to run our recursive grep for that rogue mysqladmin shutdown (or a similar, API-leveraging) process! In my case it was running on remote host 192.168.3.1 and connected as MySQL user ‘robert’.
Of course you could find alternative methods to track down MySQL connections but that’s beyond what I intended to include in this blog. Perhaps in the next?
The post When mysqld kills mysqld appeared first on MySQL Performance Blog.
If so, you might want to read on. I’m going to tell you how you can find it.