Showing posts with label patch. Show all posts
Showing posts with label patch. Show all posts

Friday, October 10, 2008

Community at work - SIGNAL


sakila signal

Long time ago, I saw a blog post by Jorge Bernal, with a simple implementation of SIGNAL for MySQL stored procedures. If you have ever tried to write MySQL stored procedures, you know how dearly missed is this feature.
I discussed this feature internally, and everyone told me "don't bother, we're going to implement SIGNAL in MySQL 6.1". And indeed, the full implementation for SIGNAL and RESIGNAL is in the roadmap.

What does that mean? Should we wait two or three more years to have a SIGNAL feature? Wouldn't it be nice to have a minimal SIGNAL working today, and get the full thing when it's ready?

A bird in the hand ...

I would like to have SIGNAL available today, and therefore I tested Jorge's patch in the latest 5.1.28 code. It needs some more twisting to get it working. If you want to try it, make sure you have the current patch.
Once you apply the patch and compile the code, you will have a server that accepts a simple "SIGNAL" command, without any parameter.
Here's a simple usage example:
First, you create two stored procedures:

delimiter //

drop procedure if exists less_than_10 //
create procedure less_than_10(i int )
deterministic
begin
if ( i < 10)
then
set @comment = concat('a valid number was entered (', i,')');
else
set @comment = concat('number too high (', i,')') ;
SIGNAL ;
end if;
select concat('everything fine [',@comment,']') as comment;
end//

drop procedure if exists trapping //
create procedure trapping ()
deterministic
begin
declare mystatus varchar(20) default 'ok';
declare continue handler for SQLSTATE '38503'
set mystatus = 'ERROR';
call less_than_10(7);
select mystatus, @comment;
call less_than_10(17);
select mystatus, @comment;
select 'and this is after the error';
end //

delimiter ;

And then we'll try out the simple one, by calling directly the procedure with a SIGNAL.

call less_than_10(2);
+--------------------------------------------------+
| comment |
+--------------------------------------------------+
| everything fine [a valid number was entered (2)] |
+--------------------------------------------------+
1 row in set (0.00 sec)
Query OK, 0 rows affected (0.00 sec)

select @comment;
+--------------------------------+
| @comment |
+--------------------------------+
| a valid number was entered (2) |
+--------------------------------+
1 row in set (0.00 sec)

call less_than_10(12);
ERROR 1340 (38503): Exception generated from user-defined function/procedure

select @comment;
+----------------------+
| @comment |
+----------------------+
| number too high (12) |
+----------------------+
1 row in set (0.00 sec)

next, we call the procedure that traps the exception. This one has full control of the execution flow, with SIGNAL and HANDLER.

call trapping();
+--------------------------------------------------+
| comment |
+--------------------------------------------------+
| everything fine [a valid number was entered (7)] |
+--------------------------------------------------+
1 row in set (0.00 sec)

+----------+--------------------------------+
| mystatus | @comment |
+----------+--------------------------------+
| ok | a valid number was entered (7) |
+----------+--------------------------------+
1 row in set (0.00 sec)

+----------+----------------------+
| mystatus | @comment |
+----------+----------------------+
| ERROR | number too high (17) |
+----------+----------------------+
1 row in set (0.00 sec)

+-----------------------------+
| and this is after the error |
+-----------------------------+
| and this is after the error |
+-----------------------------+
1 row in set (0.00 sec)

This less than 30 lines patch is much better than many hacks that we've seen published for years.
What's your take? Would you like to have this feature in MySQL 5.1, while the full thing is being developed for 6.1?

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!