Pages

Wednesday, March 19, 2008

MySQL: Finally an ability to trace/profile

Finally! The ability to look a little closer into what's happening with SHOW PROFILE


Here’s how it works:

mysql> set profiling=1;
mysql> select count(*) from mysql.user;
+----------+
| count(*) |
+----------+
| 5 |
+----------+
1 row in set (0.00 sec)

mysql> show profile;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000020 |
| checking query cache for query | 0.000250 |
| Opening tables | 0.000015 |
| System lock | 0.000010 |
| Table lock | 0.000009 |
| init | 0.000022 |
| optimizing | 0.000007 |
| executing | 0.000018 |
| end | 0.000004 |
| query end | 0.000002 |
| freeing items | 0.000019 |
| logging slow query | 0.000002 |
| cleaning up | 0.000002 |
+--------------------------------+----------+
13 rows in set (0.01 sec)

In this case, we also get info on inserts (where you don’t with explain)

mysql> create table test (id integer not null auto_increment, my_name varchar(20),primary key (id));
Query OK, 0 rows affected (0.00 sec)
mysql> insert into test (my_name) values ('Phil');
Query OK, 1 row affected (0.01 sec)

mysql> show profile;

+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000069 |
| checking permissions | 0.000008 |
| Opening tables | 0.000134 |
| System lock | 0.000004 |
| Table lock | 0.000006 |
| init | 0.000017 |
| update | 0.000093 |
| end | 0.000003 |
| query end | 0.000003 |
| freeing items | 0.002233 |
| logging slow query | 0.000003 |
| cleaning up | 0.000002 |
+----------------------+----------+

12 rows in set (0.00 sec)

Here's the steps I used to build the binaries for MySQL 5.1.24:

1) install bitkeeper client http://www.bitmover.com/bk-client2.0.shar
shell> /bin/sh bk-client2.0.shar
shell> cd bk-client2.0
shell> make
shell> make install

2) grab the current 5.1 source tree
shell> bkf clone bk://mysql.bkbits.net/mysql-5.1 mysql-5.1

3) Prepare the source for building
shell> cd mysql-5.1
shell> ./BUILD/autorun.sh

4) Build the snapshot
shell> CC=gcc CXX=gcc ./configure --prefix=/opt/app/mysql \
--localstatedir=/opt/app/mysql/data --libexecdir=/opt/app/mysql/bin \
--with-server-suffix="" --enable-thread-safe-client --enable-local-infile \
--with-pic --with-fast-mutexes --with-client-ldflags="-static" \
--with-mysqld-ldflags="-static" --with-zlib-dir=bundled --with-big-tables \
--with-ssl --with-readline --with-embedded-server --with-archive-storage-engine \
--with-blackhole-storage-engine --with-ndbcluster --with-csv-storage-engine \
--with-example-storage-engine --without-falcon --with-federated-storage-engine \
--with-partition --with-innodb --with-extra-charsets=all --enable-community-features \
--with-comment="MySQL Enterprise Server (GPL) - Snapshot from `date +'%m-%d-%Y'`"
shell> make
shell> make test

5) Make the final installer package
shell> ./scripts/make_binary_distribution

6) Then just install the binaries with the file mysql-5.1.24-rc-linux-x86_64.tar.gz


3 comments:

Anonymous said...

This is quite ingenious, I can see millions of uses for profiling in everyday coding, it's probably one of the most useful things MySQL could have done (why did this take so long?).
Profiling needs to make its way to a release version ASAP.

And thanks for letting us know, Phil!

Unknown said...

"Profiling needs to make its way to a release version ASAP."

Already in MySQL 5.0:

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 30
Server version: 5.0.45-Debian_1ubuntu3.1-log Debian etch distribution

mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from user;
+----------+
| count(*) |
+----------+
| 9 |
+----------+
1 row in set (0.00 sec)

mysql> show profile;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| (initialization) | 0.000004 |
| checking query cache for query | 0.000074 |
| Opening tables | 0.000017 |
| System lock | 0.000009 |
| Table lock | 0.000014 |
| init | 0.00002 |
| optimizing | 0.000013 |
| executing | 0.000258 |
| end | 0.00001 |
| query end | 0.000008 |
| freeing items | 0.00001 |
| closing tables | 0.000012 |
| logging slow query | 0.000006 |
+--------------------------------+----------+
13 rows in set (0.00 sec)

Cheers,

Jay

Anonymous said...

...and here there is an article that shows what information you can get from the MySQL Query Profiler