Wednesday, March 21, 2007

Rush to register for the MySQL Summer of Code (extended deadline!)



MySQL has joined Google
Summer of Code 2007 and has launched its own Summer of Code branch.

Are you a student and a skilled programmer? Do you use MySQL? Do you have ideas on how to improve it? (Do you want to use this cool logo in your blog? :) )
Here's your chance to participate. Rush to read the announcement and the full instructions in MySQL Forge and then apply!
Time is short. The deadline is Saturday, March 24, 2007 Tuesday, March 27 2007 (extended!)!

Tuesday, March 06, 2007

Federated, Blackhole, and Contributors at the MySQL Conference and Expo 2007


I will be involved in two sessions at the MySQL Users Conference and Expo 2007.
This year conference is going to be more user-oriented than ever before. Many sessions by MySQL employees will be co-presented by external users.
Some examples:
In short, there is a lot to see and do, (and not enough space in this blog). Visit the official site and judge for yourself.

Sunday, March 04, 2007

Test driving SHOW PROFILES

SHOW PROFILES is finally available! It has been a long struggle, but finally this important community patch by Jeremy Cole has been integrated into a publicly distributed MySQL source tree (thanks to Chad Miller excellent integration work).
What's SHOW PROFILES? Is a feature to let you peek inside MySQL internals, which tell you what your queries were doing during their execution.
This feature is also remarkable because it makes a significant difference between Community and Enterprise releases.
The binaries will be available soon, but in the meantime, you can build the source code and give it a try.

Building

To build from source, follow the instructions at Installing from the Development Source Tree using the Community tree.
bkf clone bk://mysql.bkbits.net/mysql-5.0-community mysql-5.0
And since this is a community feature, the documentation can be provided by the community as well. I posted a documentation stub in MySQL Forge. Feel free to add to it.

Test driving

Once you have built your community distribution (or after downloading the binaries, if you are reading this when they are already available), it's time to see what SHOW PROFILE can do.
To use this addition, you need to enable it. The session variable profiling is used to enable and disable it. By default, it is disabled, so the first order of business is: turn it on!

select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 |
+-------------+

set profiling = 1;

select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
Cool. Now what?
Now we play around with the system, and see how profiles works.

drop table if exists t1;
create table t1 (id int not null);
insert into t1 values (1), (2), (3);
select * from t1;

#
# AND FINALLY!
#

show profiles;
+----------+----------+-------------------------------------+
| Query_ID | Duration | Query |
+----------+----------+-------------------------------------+
| 0 | 0.000045 | set profiling = 1 |
| 1 | 0.000071 | select @@profiling |
| 2 | 0.000087 | drop table if exists t1 |
| 3 | 0.031741 | create table t1 (id int not null) |
| 4 | 0.000615 | insert into t1 values (1), (2), (3) |
| 5 | 0.000198 | select * from t1 |
+----------+----------+-------------------------------------+
Here is the first glimpse. Basically, it tells you the duration of each query. Not very exciting so far, but let's keep going. The Query_ID field is a reference for us, so that we can ask more about a specific query. In this list, the table creation is query no. 3, so let's ask some specifics about this one:

SHOW PROFILE FOR QUERY 3;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| checking permissions | 0.000040 |
| creating table | 0.000035 |
| After create | 0.031432 |
| query end | 0.000221 |
| freeing items | 0.000005 |
| logging slow query | 0.000006 |
| cleaning up | 0.000002 |
+----------------------+----------+
That's wonderful! Now we know more about the single tasks this query was performing. But it gets even better. Look at this:
SHOW PROFILE CPU FOR QUERY 3;
+----------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| checking permissions | 0.000040 | 0.000000 | 0.000000 |
| creating table | 0.000035 | 0.000000 | 0.000000 |
| After create | 0.031432 | 0.001000 | 0.000000 |
| query end | 0.000221 | 0.000000 | 0.000000 |
| freeing items | 0.000005 | 0.000000 | 0.000000 |
| logging slow query | 0.000006 | 0.000000 | 0.000000 |
| cleaning up | 0.000002 | 0.000000 | 0.000000 |
+----------------------+----------+----------+------------+
If you are debugging code, you may like the information provided by the following option:
SHOW PROFILE source FOR QUERY 3;
+----------------------+----------+-----------------------+--------------+-------------+
| Status | Duration | Source_function | Source_file | Source_line |
+----------------------+----------+-----------------------+--------------+-------------+
| checking permissions | 0.000040 | check_access | sql_parse.cc | 5256 |
| creating table | 0.000035 | mysql_create_table | sql_table.cc | 1737 |
| After create | 0.031432 | mysql_create_table | sql_table.cc | 1768 |
| query end | 0.000221 | mysql_execute_command | sql_parse.cc | 5085 |
| freeing items | 0.000005 | mysql_parse | sql_parse.cc | 5973 |
| logging slow query | 0.000006 | log_slow_statement | sql_parse.cc | 2178 |
| cleaning up | 0.000002 | dispatch_command | sql_parse.cc | 2143 |
+----------------------+----------+-----------------------+--------------+-------------+
It tells you how much time was spent, and which lines of code you should look at if you want to improve it!
More options available in the documentation stub.
Rather than trying all of them here, I will just give you a simple example of what can be hidden behind a query. Check this out:
connect;
set profiling=1;
use information_schema;
select count(*) from columns where table_schema='mysql';
+----------+
| count(*) |
+----------+
| 147 |
+----------+

show profiles;
+----------+----------+---------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+----------+---------------------------------------------------------+
| 0 | 0.000194 | set profiling=1 |
| 1 | 0.000006 | SELECT DATABASE() |
| 2 | 0.005928 | select count(*) from columns where table_schema='mysql' |
+----------+----------+---------------------------------------------------------+

show profile for query 2;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| Opening tables | 0.000051 |
| System lock | 0.000281 |
| Table lock | 0.000002 |
| init | 0.000006 |
| optimizing | 0.000020 |
| statistics | 0.000009 |
| preparing | 0.000012 |
| executing | 0.000011 |
| checking permissions | 0.000039 |
| Opening tables | 0.000136 |
| checking permissions | 0.000010 |
| Opening tables | 0.000185 |
| checking permissions | 0.000008 |
| Opening tables | 0.000478 |
| checking permissions | 0.000007 |
| Opening tables | 0.000107 |
| checking permissions | 0.000006 |
| Opening tables | 0.000096 |
| checking permissions | 0.000006 |
| Opening tables | 0.000052 |
| checking permissions | 0.000006 |
| Opening tables | 0.000051 |
| checking permissions | 0.000007 |
| Opening tables | 0.000145 |
| checking permissions | 0.000006 |
| Opening tables | 0.000445 |
| checking permissions | 0.000007 |
| Opening tables | 0.000395 |
| checking permissions | 0.000007 |
| Opening tables | 0.000189 |
| checking permissions | 0.000007 |
| Opening tables | 0.000195 |
| checking permissions | 0.000005 |
| Opening tables | 0.000053 |
| checking permissions | 0.000006 |
| Opening tables | 0.000055 |
| checking permissions | 0.000005 |
| Opening tables | 0.000058 |
| checking permissions | 0.000005 |
| Opening tables | 0.000064 |
| checking permissions | 0.000005 |
| Opening tables | 0.000123 |
| checking permissions | 0.000007 |
| Sending data | 0.000898 |
| end | 0.001215 |
| query end | 0.000007 |
| freeing items | 0.000003 |
| closing tables | 0.000010 |
| removing tmp table | 0.000002 |
| closing tables | 0.000420 |
| logging slow query | 0.000003 |
| cleaning up | 0.000002 |
+----------------------+----------+
52 rows in set (0.00 sec)
Now it's your turn to experiment and share your experiences!