Wednesday Apr 16, 2008

Dtrace with MySQL 6.0.5 - on a Mac

For the first time, MySQL includes Dtrace probes in the 6.0 release. On platforms that support Dtrace you can still find out a lot about what's happening, both in the Operating System kernel and in user processes, even without probes in the application. But carefully placed Dtrace probes inserted into the application code can give you a lot more information about what's going on, because they can be mapped to the application functionality. So far only a few probes have been included, but expect more to be added soon.

I decided to take the new probes for a spin. Oh, and rather than do it on a Solaris system, I figured I'd give it a shot on my Intel Core 2 Duo MacBook Pro, since MacOS X 10.5 (Leopard) supports Dtrace.

To begin with I pulled down and built MySQL 6.0.5 from Bit Keeper, thanks to some help from Brian Aker. Here's where, and here's how. I needed to make a couple of minor changes to the dtrace commands in the Makefiles to get it to compile - hopefully that will be fixed pretty soon in the source. Before long I had mysqld running. A quick "dtrace -l | grep mysql" confirmed that I did indeed have the Dtrace probes.

There are lots of interesting possibilities, but for now I'll just run a couple of simple scripts to illustrate the basics.

First, I ran this D script:

#!/usr/sbin/dtrace -s

:mysqld::
{
	printf("%d\\n", timestamp);
}

Running "select count(\*) from latest" from mysql in another window yielded the following:

dtrace: script './all.d' matched 16 probes
CPU     ID                    FUNCTION:NAME
  0  18665 _ZN7handler16ha_external_lockEP3THDi:external_lock 26152931955098

  0  18673 _Z13handle_selectP3THDP6st_lexP13select_resultm:select_start 26152931997414

  0  18665 _ZN7handler16ha_external_lockEP3THDi:external_lock 26153878060162

  0  18672 _Z13handle_selectP3THDP6st_lexP13select_resultm:select_finish 26153878082583

So the count(\*) took out a couple of locks, and we got to see the start and end of the select with a timestamp (in microseconds). Just for interest, I ran the count(\*) a second time, and this time none of the probes fired - the query was being satisfied from the query cache.

Next I decided to try "show indexes from latest;". The result was as follows:

mysql> show indexes from latest;
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table  | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_Comment |
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| latest |          0 | latest_x |            1 | hostid      | A         |      356309 |     NULL | NULL   | YES  | BTREE      |         |               | 
| latest |          0 | latest_x |            2 | exdate      | A         |      356309 |     NULL | NULL   | YES  | BTREE      |         |               | 
| latest |          0 | latest_x |            3 | extime      | A         |      356309 |     NULL | NULL   | YES  | BTREE      |         |               | 
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
3 rows in set (0.15 sec)

Here's the result from Dtrace:

  0  18673 _Z13handle_selectP3THDP6st_lexP13select_resultm:select_start 27114155991557

  0  18670 _ZN7handler12ha_write_rowEPh:insert_row_start 27114308499688

  0  18669 _ZN7handler12ha_write_rowEPh:insert_row_finish 27114308553968

  0  18670 _ZN7handler12ha_write_rowEPh:insert_row_start 27114308565086

  0  18669 _ZN7handler12ha_write_rowEPh:insert_row_finish 27114308588605

  0  18670 _ZN7handler12ha_write_rowEPh:insert_row_start 27114308598685

  0  18669 _ZN7handler12ha_write_rowEPh:insert_row_finish 27114308622164

  0  18672 _Z13handle_selectP3THDP6st_lexP13select_resultm:select_finish 27114308714705

So three rows were inserted, presumably into a temporary table, corresponding to the three index columns. Dtrace shows that the query cache isn't used when you rerun this particular query.

Next I ran the following D script:

#!/usr/sbin/dtrace -s

:mysqld::\*_start
{
	self->ts = timestamp;
}

:mysqld::\*_finish
/self->ts/
{
	printf("%d\\n", timestamp - self->ts);
}

and reran the "show indexes" command. Here's the result:

CPU     ID                    FUNCTION:NAME
  1  18669 _ZN7handler12ha_write_rowEPh:insert_row_finish 61634

  1  18669 _ZN7handler12ha_write_rowEPh:insert_row_finish 22040

  1  18669 _ZN7handler12ha_write_rowEPh:insert_row_finish 21058

  1  18672 _Z13handle_selectP3THDP6st_lexP13select_resultm:select_finish 88933

This time we see just one line for each insert and select, including the time taken to complete the operation (in microseconds) rather than a timestamp.

Even in the more compact form, this would get a bit verbose for some operations, though, so I ran the following D script:

#!/usr/sbin/dtrace -s

:mysqld::\*_start
{
	self->ts = timestamp;
}

:mysqld::\*_finish
/self->ts/
{
	@completion_time[probename] = quantize(timestamp - self->ts);
}

After repeating the "show indexes", Dtrace returned the following after a Control-C:

dtrace: script './all3.d' matched 12 probes
\^C

  insert_row_finish                                 
           value  ------------- Distribution ------------- count    
            8192 |                                         0        
           16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2        
           32768 |@@@@@@@@@@@@@                            1        
           65536 |                                         0        

  select_finish                                     
           value  ------------- Distribution ------------- count    
           32768 |                                         0        
           65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
          131072 |                                         0        

This actually gives more info, but in a fairly compact form. Thanks to the quantize() function, we see a histogram with a count for each operation alongside the time taken; Two of the inserts completed in roughly 16384 microseconds, and one in 32768 microseconds.

Finally, I ran a "show tables;", which returned 48 rows, and the following from Dtrace:

dtrace: script './all3.d' matched 12 probes
\^C

  select_finish                                     
           value  ------------- Distribution ------------- count    
           32768 |                                         0        
           65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
          131072 |                                         0        

  insert_row_finish                                 
           value  ------------- Distribution ------------- count    
            4096 |                                         0        
            8192 |@@@@@@@@@@@@                             14       
           16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@             33       
           32768 |@                                        1        
           65536 |                                         0        

The report shows the 46 inserts. It would have been a lot more difficult to read with the first couple of D scripts, but the quantize() function offers a nice summary for no effort.

This is barely scratching the surface of what Dtrace can do, of course. But hopefully I've whetted your appetite. Why don't you check it out for yourself?

About

I'm a Principal Engineer in the Performance Technologies group at Sun. My current role is team lead for the MySQL Performance & Scalability Project.

Search

Categories
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