Using DTrace to observe the SQL statements on a live running MySQL database

DTrace allows you to instrument any live running application in production without the need of extra coding, application recompile or even an application restart. All you need is that the application is running on an OS that supports DTrace. Today Solaris, OpenSolaris, OS X and FreeBSD are a few that have DTrace built in.

For example here is a D-script that instrument MySQL to observe the SQL statements that is being executed in production. Just a 3 line script like this can be extremely useful to observe a live MySQL database

#!/usr/sbin/dtrace -qs
pid$1::\*dispatch_command\*:entry
{
    printf("%d::%s\\n",tid,copyinstr(arg2));
}
You need to pass the pid of the mysql process as the first argument to this script.

Here is a sample output from the script. We are observing the SQL statements that are executed to bring up the SugarCRM login screen.


# pgrep mysql
418
254
# ./mysql.d 418
11::sugarcrm
11::SET CHARACTER SET utf8
11::SET NAMES 'utf8'
11::SELECT id, name, symbol, conversion_rate FROM currencies WHERE
status = 'Active' and deleted = 0
11::SELECT category, name, value FROM config
11::SELECT id FROM outbound_email WHERE type = 'system'
11::SELECT \* FROM outbound_email WHERE id =
'592d612d-3fd2-fa02-f067-48d0467e2da0'
11::
12::sugarcrm
12::SET CHARACTER SET utf8
12::SET NAMES 'utf8'
12::SELECT id, name, symbol, conversion_rate FROM currencies WHERE
status = 'Active' and deleted = 0
12::SELECT category, name, value FROM config
12::SELECT id FROM outbound_email WHERE type = 'system'
12::SELECT \* FROM outbound_email WHERE id =
'592d612d-3fd2-fa02-f067-48d0467e2da0'
12::SELECT acl_actions .\*, acl_roles_actions.access_override
                   FROM acl_actions
                   LEFT JOIN acl_roles_users ON
acl_roles_users.user_id = '' AND  acl_roles_users.deleted = 0
                   LEFT JOIN acl_roles_actions
12::SELECT count(\*) as the_count FROM config WHERE category='info' AND
name='sugar_version' AND value = '5.1.0'
12::SELECT category, name, value FROM config
12::SELECT id FROM outbound_email WHERE type = 'system'
12::SELECT \* FROM outbound_email WHERE id =
'592d612d-3fd2-fa02-f067-48d0467e2da0'
12::INSERT INTO tracker
(monitor_id,module_name,date_modified,action,session_id ) VALUES (
'97e1d39b-c036-1e1f-bf2f-48f763a6045c','Users','2008-10-16
15:53:13','login','8fbb9c1a0ac421964fa4a45db4086a46')
12::SELECT user_name FROM users WHERE id='1'

Please note you do not need anything special from MySQL. This will run with any plain vanilla mysql instance with no restart or special flags

How does the script work
We are using the pid provider in DTrace to instrument the dispatch_command method of the live running MySQL instance. This is the method that is called when any SQL statement is executed. The third argument for this method is a string that contains the SQL statement. We are just printing the third argument in the D-script

As always let me know if you need more details
Comments:

Great post! Since I use more Oracle than MySQL, does anyone know the method name Oracle uses?

Posted by Bob on October 16, 2008 at 07:13 AM EST #

Is it possible to filter these queries for connection? Let say in a based tcp-connection to the server, so that you can see the queries of single client?

This is very interesting in cases of performance load tests on application.

Posted by periklis on October 16, 2008 at 09:41 AM EST #

Why not use MySQLProxy instead in this instance ?

Posted by Jared on October 16, 2008 at 11:34 AM EST #

Why is Linux not listed as a supported OS ?!? Who cares about Solaris ? Solaris is supported and Linux is not ?

Developers were afraid from day 1 that Sun will try to make Linux the second OS choice for MySql.

Posted by Razvan on October 16, 2008 at 06:17 PM EST #

Razvan,

Linux is not listed because Linux doesn't provide DTrace support. That has nothing to do with Sun closing anything (DTrace is open source, after all, being part of OpenSolaris) or neglecting Linux.

Check http://blogs.sun.com/ahl/entry/what_if_machine_dtrace_port for details.
I for one would be delighted if the Linux community decides to support DTrace (like FreeBSD and Apple did), it would make my life so much easier.

Posted by Kay Röpke on October 16, 2008 at 07:57 PM EST #

periklis,

filtering by TCP connection is harder (and the IP provider doesn't have many probes yet, and is only available on Solaris, IIRC).
However, if you know the MySQL thread id (tid in the above), you can add that as a predicate expression in your D script.

Posted by Kay Röpke on October 16, 2008 at 07:59 PM EST #

Razvan,

Linux stay the number 1 choice for MySQL community users, but MySQL policy is to stay neutral regarding OS usage.

We are waiting for a port of Dtrace to Linux and this have already been advanced by SUN Mic.

Many OS will benefit from the multi core scalability currently driven by the Solaris world.

From MySQL 5.1 query logging can be activated on the fly.

Posted by Stephane on October 16, 2008 at 08:08 PM EST #

Jared, this is because Linux doesn't support DTrace, they have different thing. And you see that it works also on FreeBSD, OS X, which are not affiliated with SUN/MySQL.

Posted by Andrey on October 16, 2008 at 11:20 PM EST #

Nice. I posted a gist with instructions for making this a one word command (e.g. sqllog) in OS X:

http://gist.github.com/17521

Posted by Marcus on October 17, 2008 at 08:46 AM EST #

Very cool.

Jared, Dtrace need to be implemented into the Linux Kernel and as CDDL and GPL are not compatible, Linux don't support Dtrace/ZFS yet.

Posted by Silveira Neto on January 09, 2009 at 06:39 AM EST #

The TID in dtrace does not seem to correspond to the MySQL internal thread_id.

The "ID" in "show processlist" is another ID. but even when I use the above script to do dtrace (Solaris 10). the TID always display as "2". even I issued different SQL from different sessions.

The MySQL Version:

bash-3.00$ mysql --version
mysql Ver 14.12 Distrib 5.0.36-br13799, for pc-solaris2.10 (i386) using EditLine wrapper

On another busy system with hundreds of busy sessions, the TID does changed, 10, 15, 3, 5.....but it did not seem to map to the individual sessions. e.g. Thread_id 10 showing up most of the time, while all sessions should be load-balanced.

I wonder if anyone has tried to look into the THD class of MySQL. can dtrace grab the THD->thread_id? It would be simpler to use the ID in "show processlist" to trace a single session....

Thanks,

Posted by Geo on May 19, 2009 at 08:47 AM EST #

Post a Comment:
  • HTML Syntax: NOT allowed
About

angelo

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today
News
Blogroll

No bookmarks in folder