Tip

Examining MySQL in real time using DTrace

DTrace, the Dynamic Tracing facility currently available on OSes including Mac OS X, FreeBSD, and of course Solaris, provides a unique way to peer into the inner workings of MySQL even when under the most brutal of production workloads.

Contrary to popular belief, MySQL does not need to be modified for

Requires Free Membership to View

DTrace to be effective. One of DTrace's most powerful "providers" (a grouping of observable probes) is the Functional Boundary Tracing (FBT) provider. FBT can see the entry or return of any C function. We combine this with the PID provider to peer into userland processes. We can exploit these capabilities with a basic understanding of the MySQL code.

How do we get to know the MySQL code? There are two ways. The first is to buy a good book such as MySQL Internals. If you're serious about MySQL, you must have a copy of this book. The second is DTrace itself. One of DTrace's greatest features is a pragma option called "flowindent". This function shows entry and return properly indented, forming a logic tree so that you can see what is calling what. In this way we can actually see MySQL's inner monologue, if you will. Every function streams by in real time.

Here is the code itself (mysqlflow.d):




#!/usr/sbin/dtrace -s

#pragma D option flowindent

pid$target:mysqld::entry
{
}
pid$target:mysqld::return
{
}

Put this in a file and make it executable. Here we're using the PID provider to look into the 'mysqld' process. Because we're not specifying a "function" (remember, probe form is PROVIDER:MODULE:FUNCTION:NAME) it is interpreted as a wildcard. Thus we will see all functions. The initial probe names are for entry and return of each function.

When we run this we need to use the DTrace -p flag to specify the process id (PID) of the mysql daemon itself, which we can get conveniently on Solaris via the "pgrep" command:




# ./mysqlflow.d -p `pgrep -x mysqld`
 0  -> sync_array_get_nth_cell       
 0  <- sync_array_get_nth_cell       
 0 <- sync_array_print_long_waits      
 0 -> os_thread_sleep            
 2 <- os_thread_sleep            
 2 -> sync_arr_wake_threads_if_sema_free  
 2  -> sync_array_enter          
 2   -> os_mutex_enter          
 2    -> os_fast_mutex_lock       
 2    <- os_fast_mutex_lock       
 2   <- os_mutex_enter          
 2  <- sync_array_enter          
 2  -> sync_array_exit           
 2   -> os_mutex_exit           
 2    -> os_fast_mutex_unlock      
 2    <- os_fast_mutex_unlock      
 2   <- os_mutex_exit           
 2  <- sync_array_exit           
 2 <- sync_arr_wake_threads_if_sema_free 
...

Use ^C to end the trace. Just this alone can provide hours of entertainment and enlightenment.

The first thing you'll notice is that InnoDB is very chatty even when the database is idle. A seemingly constant flow of 'sync_array_get_nth_cell()' functions are the result of InnoDB checkpoints.

The example above demonstrates DTrace's ability to watch MySQL functions coming and going in real time, but to be of any use we need to know what's being passed into these functions. We need to look at certain functions and their arguments. We all like to spy, right? What if I told you that without logging into the database or looking at any logs I can see every query that MySQL processes? By tracing an argument of "dispatch_command()" I can do just that.

Here is the script (query_watch.d):




#!/usr/sbin/dtrace -s

#pragma D option quiet

pid$target:mysqld:*dispatch_command*:entry
{
 printf("Query: %s\n", copyinstr(arg2));
}

Again, save that to a text file and make executable and execute with '-p PID'. Use ^c to stop tracing.




# query_watch.d -p `pgrep -x mysqld`
Query: show tables
Query: select * from Country LIMIT 10
Query: explain user
...

Because we're able to see queries entering the MySQL dispatcher in real time just watching the queries fly by, we can easily identify patterns and trends. Were you aware that your CRM was executing hundreds of identical queries every second?

For those of you reading this who have just realized the security implications of what I'm teaching you to do, you'll be happy to know that only root (or an explicitly authorized user in Solaris) can run DTrace. If your knee-jerk reaction is to be scared of MySQL on a DTrace capable system, remember that we can use DTrace like this for - Oracle, PostgreSQL, Mozilla or any other application. DTrace sees all. If you've never understood the full power of DTrace, I hope it's sinking in.

Now, lets take this example a little further. Duplicate queries can be a big problem, commonly suggesting poor client-side caching or application logic. Let's use a DTrace aggregation to count up all those queries and report on how many times each query is getting hammered during a given period.

Here is the script (querycounts.d):




#!/usr/sbin/dtrace -s

#pragma D option quiet

dtrace:::BEGIN
{
    printf("Tracing... Hit Ctrl-C to end.\n");
}

pid$target::*dispatch_command*:entry
{
    @query[copyinstr(arg2)] = count();
}

When this script is run, it will begin collecting data and won't actually output its report until it completes. The aggregation function count() is filling up @query with the results of arg2 passed to the "dispatch_command" function.




# querycounts.d -p `pgrep -x mysqld`
Tracing... Hit Ctrl-C to end.

^C
 
 select * from CountryLanguage LIMIT 5  1
 show tables     4
 select * from City    10

Obviously, this example output isn't from a real production system. When using in production, you may expect far more output.

The examples we've covered here are only the tip of an iceburg of possibility. When you combine a good MySQL internals reference book with the ability to watch the flow of functions within MySQL, you'll quickly start to understand it in a way you never imagined possible. With this newfound knowledge you'll be able to leverage DTrace to quickly pierce into parts of the code of production workloads. Then, you'll be able to comprehend behavior that you couldn't do so in any other way.

I hope this puts you on solid footing to go forward. Use it to learn, impress your coworkers or save the day. Happy tracing.

Special thanks to Derek Crudgington.

ABOUT THE AUTHOR: Ben Rockwood is the Director of Systems at the cloud computing. infrastructure company Joyent, Inc. A Solaris expert and Sun evangelist, he lives just outside of the Silicon Valley with his smokin' hot wife, Tamarah, and their 3 children. Read his blog at cuddletech.com.
 

This was first published in November 2008

There are Comments. Add yours.

 
TIP: Want to include a code block in your comment? Use <pre> or <code> tags around the desired text. Ex: <code>insert code</code>

REGISTER or login:

Forgot Password?
By submitting you agree to receive email from TechTarget and its partners. If you reside outside of the United States, you consent to having your personal data transferred to and processed in the United States. Privacy
Sort by: OldestNewest

Forgot Password?

No problem! Submit your e-mail address below. We'll send you an email containing your password.

Your password has been sent to:

Disclaimer: Our Tips Exchange is a forum for you to share technical advice and expertise with your peers and to learn from other enterprise IT professionals. TechTarget provides the infrastructure to facilitate this sharing of information. However, we cannot guarantee the accuracy or validity of the material submitted. You agree that your use of the Ask The Expert services and your reliance on any questions, answers, information or other materials received through this Web site is at your own risk.