Over a million developers have joined DZone.
{{announcement.body}}
{{announcement.title}}

When MySQLd Kills MySQLd

DZone's Guide to

When MySQLd Kills MySQLd

Get the tools and know-how needed to analyze cryptic MySQL logs and track down the rogue processes that send signals to mysqld.

· Database Zone
Free Resource

Download the Guide to Open Source Database Selection: MySQL vs. MariaDB and see how the side-by-side comparison of must-have features will ease the journey. Brought to you in partnership with MariaDB.

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 shutdown by 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?

Robert joined the US consulting team of Percona in 2014. He is an avid fan of opensource and all things IT. Before joining Percona he worked in various roles for a Fortune 500 manufacturing company, most recently as an Infrastructure Architect / Engineer. He is originally from Europe, Hungary where he used to be an instructor and taught various Sun Microsystems classes across Europe. Robert has some academic background and he used to manage the network services of his old Department and his Dormitory. In those rare hours when he is not in front of a computer he spends time with his family or plays around with his RC gear.

Interested in reducing database costs by moving from Oracle Enterprise to open source subscription?  Read the total cost of ownership (TCO) analysis. Brought to you in partnership with MariaDB.

Topics:
devops ,mysql

Published at DZone with permission of Peter Zaitsev, DZone MVB. See the original article here.

Opinions expressed by DZone contributors are their own.

THE DZONE NEWSLETTER

Dev Resources & Solutions Straight to Your Inbox

Thanks for subscribing!

Awesome! Check your inbox to verify your email so you can start receiving the latest in tech news and resources.

X

{{ parent.title || parent.header.title}}

{{ parent.tldr }}

{{ parent.urlSource.name }}