I’ve been playing more with the SHOW PROFILE command available as part of MySQL Community 5.0.37. Thanks to the author Jeremy Cole. This command can provide some interesting insight into the workings of MySQL. It does however like most new releases of software enable users to make suggestions for new features and functionality. Here is my wish list. Some I figure are practical, some are wish list, but if you never ask you never know.

1. The Unit of measure for duration is Second. It would be great if it could be tuned for display, say millisecond. If you look at my first Example, all figures are effectively represented in milli-second or even micro-second granularity.
2. I would like to see a total for the query. Again in Example 1, you have to add up all the figures to determine this query took 8ms.
3. Again in Example 1, perhaps a percentage of total time for each line duration may be helpful.
4. More descriptive status descriptions (this is part of the MySQL internal code and not the patch)
5. SET PROFILING=1; can only be set on a current session, making it impossible to easily monitor a JDBC multi-connection test. There needs to be a way to enable for a session, other then current interactive one you are viewing, but also be able to see results. You can’t do a SHOW PROFILE via a JDBC connection!
6. I’d like to see a threshold, so queries running under threshold are discarded, much like a long-query-time option. This enables you to run a large number of SQL Statements and only profiles for longer running ones are logged
7. I’d like to see a level of logging to file, again like a slow query log, so you can simply gather information on a working system and review at some later time. Combined with the previous point, you now have microsecond slow query log with explicit details.

One major benefit of the SHOW PROFILE command is I can accurately get a figure for how long a query it taking (time in milliseconds). You just have to sum all figures (See wish list point 2).

By default, the source details are not provided, you need to specify the SOURCE operand, which helps in both comparing with any debugging output and also trouncing through the code. As in Example 1, I needed to find why 95% of time was in a step with the most descriptive line of ‘end’.

Example 1

mysql> show profile SOURCE,MEMORY for query 4;
+--------------------+------------+-----------------------+---------------+-------------+
| Status             | Duration   | Source_function       | Source_file   | Source_line |
+--------------------+------------+-----------------------+---------------+-------------+
| Opening tables     | 0.00013200 | open_tables           | sql_base.cc   |        2106 |
| System lock        | 0.00001800 | mysql_lock_tables     | lock.cc       |         153 |
| Table lock         | 0.00000600 | mysql_lock_tables     | lock.cc       |         162 |
| init               | 0.00001300 | mysql_select          | sql_select.cc |        2073 |
| optimizing         | 0.00004800 | optimize              | sql_select.cc |         617 |
| statistics         | 0.00002500 | optimize              | sql_select.cc |         773 |
| preparing          | 0.00005200 | optimize              | sql_select.cc |         783 |
| executing          | 0.00002200 | exec                  | sql_select.cc |        1407 |
| Sending data       | 0.00000500 | exec                  | sql_select.cc |        1925 |
| end                | 0.00786600 | mysql_select          | sql_select.cc |        2118 |
| query end          | 0.00001400 | mysql_execute_command | sql_parse.cc  |        5085 |
| freeing items      | 0.00000700 | mysql_parse           | sql_parse.cc  |        5973 |
| closing tables     | 0.00001900 | dispatch_command      | sql_parse.cc  |        2120 |
| logging slow query | 0.00001000 | log_slow_statement    | sql_parse.cc  |        2178 |
| cleaning up        | 0.00000500 | dispatch_command      | sql_parse.cc  |        2143 |
+--------------------+------------+-----------------------+---------------+-------------+
15 rows in set (0.01 sec)

Example 2

We were experiencing increased latency in JDBC with a particular query, With a recommendation from MySQL Support we tried SET SQL_BUFFER_RESULT=1;

mysql> show profile source for query 14;
+------------------------------+------------+-------------------------+---------------+-------------+
| Status                       | Duration   | Source_function         | Source_file   | Source_line |
+------------------------------+------------+-------------------------+---------------+-------------+
| Opening tables               | 0.00006025 | open_tables             | sql_base.cc   |        2106 |
| System lock                  | 0.00004875 | mysql_lock_tables       | lock.cc       |         153 |
| Table lock                   | 0.00000400 | mysql_lock_tables       | lock.cc       |         162 |
| init                         | 0.00001600 | mysql_select            | sql_select.cc |        2073 |
| optimizing                   | 0.00005675 | optimize                | sql_select.cc |         617 |
| statistics                   | 0.00001250 | optimize                | sql_select.cc |         773 |
| preparing                    | 0.00005175 | optimize                | sql_select.cc |         783 |
| Creating tmp table           | 0.00001275 | optimize                | sql_select.cc |        1206 |
| executing                    | 0.00006025 | exec                    | sql_select.cc |        1407 |
| Copying to tmp table         | 0.00000400 | exec                    | sql_select.cc |        1547 |
| converting HEAP to MyISAM    | 0.04820900 | create_myisam_from_heap | sql_select.cc |        9914 |
| Copying to tmp table on disk | 0.04049075 | create_myisam_from_heap | sql_select.cc |        9968 |
| Sending data                 | 1.29302000 | exec                    | sql_select.cc |        1925 |
| end                          | 0.09398425 | mysql_select            | sql_select.cc |        2118 |
| removing tmp table           | 0.00004975 | free_tmp_table          | sql_select.cc |        9856 |
| end                          | 0.00089125 | free_tmp_table          | sql_select.cc |        9884 |
| query end                    | 0.00001850 | mysql_execute_command   | sql_parse.cc  |        5085 |
| freeing items                | 0.00000825 | mysql_parse             | sql_parse.cc  |        5973 |
| closing tables               | 0.00003425 | dispatch_command        | sql_parse.cc  |        2120 |
| logging slow query           | 0.00001325 | log_slow_statement      | sql_parse.cc  |        2178 |
| cleaning up                  | 0.00000675 | dispatch_command        | sql_parse.cc  |        2143 |
+------------------------------+------------+-------------------------+---------------+-------------+
21 rows in set (0.00 sec)

Looking at the lines helped to indicate that the temporary table was being flushed to disk, indicating we need to Add SET SESSION tmp_table_size=20*1024*1024;

mysql> show profile source for query 18;
+----------------------+------------+-----------------------+---------------+-------------+
| Status               | Duration   | Source_function       | Source_file   | Source_line |
+----------------------+------------+-----------------------+---------------+-------------+
| Opening tables       | 0.00006050 | open_tables           | sql_base.cc   |        2106 |
| System lock          | 0.00001250 | mysql_lock_tables     | lock.cc       |         153 |
| Table lock           | 0.00000400 | mysql_lock_tables     | lock.cc       |         162 |
| init                 | 0.00000775 | mysql_select          | sql_select.cc |        2073 |
| optimizing           | 0.00005475 | optimize              | sql_select.cc |         617 |
| statistics           | 0.00001225 | optimize              | sql_select.cc |         773 |
| preparing            | 0.00005075 | optimize              | sql_select.cc |         783 |
| Creating tmp table   | 0.00001350 | optimize              | sql_select.cc |        1206 |
| executing            | 0.00006125 | exec                  | sql_select.cc |        1407 |
| Copying to tmp table | 0.00000375 | exec                  | sql_select.cc |        1547 |
| Sending data         | 0.29110925 | exec                  | sql_select.cc |        1925 |
| end                  | 0.08023800 | mysql_select          | sql_select.cc |        2118 |
| removing tmp table   | 0.00001525 | free_tmp_table        | sql_select.cc |        9856 |
| end                  | 0.05971400 | free_tmp_table        | sql_select.cc |        9884 |
| query end            | 0.00001925 | mysql_execute_command | sql_parse.cc  |        5085 |
| freeing items        | 0.00000425 | mysql_parse           | sql_parse.cc  |        5973 |
| closing tables       | 0.00004625 | dispatch_command      | sql_parse.cc  |        2120 |
| logging slow query   | 0.00000800 | log_slow_statement    | sql_parse.cc  |        2178 |
| cleaning up          | 0.00000300 | dispatch_command      | sql_parse.cc  |        2143 |
+----------------------+------------+-----------------------+---------------+-------------+
19 rows in set (0.00 sec)

On Thursday I saw something I’d not seen before. An Empty Innodb Status. Now given the amount of output normally shown it was certainly a first. And it looked like:

mysql> SHOW ENGINE INNODB STATUS;
+--------+------+--------+
| Type   | Name | Status |
+--------+------+--------+
| InnoDB |      |        |
+--------+------+--------+
1 row in set (0.03 sec)

To answer some of the most obvious questions.

• Yes it was a working existing MySQL instance, with InnoDB correctly configured. Indeed we had been benchmarking for several hours.
• MySQL Server was running, indeed a command selecting data from the mysql schema worked just fine after seeing this (All other tables were Innodb).
• Absolutely nothing in the host MySQL error log. (This was the second most disappointing aspect)
• The Process List showed two queries that had been running for some time, everything was taking  ; 1 second. (This was the most disappointing)

So the problem is, MySQL seems to effectively hung when dealing with queries solely in InnoDB tables. Closer investigation found that another application process had filled the /tmp file system. Reclaiming space didn’t cause MySQL and InnoDB to start operating. Even a shutdown of MySQL failed, with mysqld having to be killed manually

For those super inquisitive the version was 5.1.16-ndb-6.2.0-log, and yes it is a Cluster release. I’ve yet to test the problem on a normal 5.1 version and log a bug appropriately if it exists.

I suspect in our benchmark we definitely need to include some timeout handling, so the queries would fail (they were both UPDATES), but it did have the customer asking why, do which there was no answer.

For all those instant GUI people out there, there is an easy way to watch the present status of your MySQL Slaves using the watch command.

$ watch -n 1 -d "mysql -uroot -pxxxx mysql -e 'SHOW SLAVE STATUS\G'"

The watch provides a view of a file or command, and shows interval updates to this output (-n  seconds> option). You can also specific a granularity better then one second for example 0.5. -d also highlights the differences for you. So while you see the following output with your SHOW SLAVE STATUS, on a loaded system you will also see bin-log and relay-log changes, and perhaps Seconds_Behind_Master.

The question is, Why is Seconds_Behind_Master the last column in this display?


*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: localhost
Master_User: repl
Master_Port: 10002
Connect_Retry: 60
Master_Log_File: master-bin.000006
Read_Master_Log_Pos: 102
Relay_Log_File: newyork-relay-bin.000055
Relay_Log_Pos: 244
Relay_Master_Log_File: master-bin.000006
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 102
Relay_Log_Space: 539
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 0

With my very heavy travel load and skilling load I’ve not had time to scratch myself. It hasn’t stopped the brain working overtime on various issues including the classic find a pattern in a string starting with a wildcard character. On a recent gig I saw the true classic.


SELECT columns
FROM users
WHERE username LIKE '%str%'
OR firstname LIKE '%str%'
OR lastname LIKE '%str%'

I went through the various options and comments on leading ‘%’, OR’s, combined columns, FULLTEXT (which doesn’t work in this case), merge indexing etc, however it perplexed me that nobody has really solved this problem, or at least shared their solutions.

I have an idea, a theory and while I’d love to prove/disprove it, I simply just don’t have the time. So here are my notes, hopefully somebody can comment positively/negatively, do some research, or encourage me to pursue it more.

The Problem

The problem is quite simply the leading wildcard, Der!. So how do you eliminate the wildcard from the search?

My Idea

Working with the earlier example, and having a concatenated field of the three components (username,firstname,lastname), my idea is to encode into 27 bits, a bit for each alphabetic character (A-Z) found, and any non-alphabetic character except whitespace in bit 27.

This column is then indexed and searched for bitwise matches. Here is a pictorial description.

My idea is very simple, the question is, will it actually work.

The Questions

The goal is quite obviously to get an Index utilization, to a maximum say of 10%-25% of matching rows. Factors that would affect this include:

• If search string is one character, like a vowel I could this not useful, so an implied criteria for optimal work is at least 2 or 3 characters.
• I see the effectiveness lost on large column values, it could be that only up to say 30 characters is optimal, I see strings of 100+ characters would be ineffective.
• It doesn’t support case-sensitive searching or non ASCII searching

The Tests

• Create good sized table and distribution of first/last names (A IMDB Actors table would work)
• Create a concatenated column of searchable fields (e.g. details = CONCAT_WS(‘ ‘,firstname,lastname)
• Create function to return bitwised search string (e.g. bitize(str))
• Create Indexed bitwise column and pre-populate accordingly (e.g. bitfulldetails)
• Create BEFORE INSERT|BEFORE UPDATE Triggers to populate Indexed bitwised column
• Test the sucker (of course you will need to include the actual LIKE command as well in the WHERE clause)

A sample query would then be:


SELECT columns
FROM users
WHERE bitize('str') & bitfulldetails
AND fulldetails like '%str%'


So the challenge to all those budding MySQL Gurus, does it seem plausible?

At a customer site recently I came across the following table definition for an Innodb table. 140 columns, 3 part primary key totally 44 bytes, 2 million rows giving over 900MB in data size. And it had 15 indexes, totaling over 2.3GB in size. Add into the mix a Windows Server 2003 OS, 640MB innodb_buffer_pool_size setting and table scans out the warzoo. This all leads to very poor performance.

In is generally considered best practice for Innodb to use the shortest primary key as possible, and there is a clear reason for this. Innodb stores with every index the full primary key. So for example if an indexed column was 4 bytes in length, in this example the index row would be 48 bytes (before overhead). Fortunately an easy solution presented itself, because of this index storage requirement, Innodb will create an internal 6 byte primary key if none exists for a table. I of course had known about this but had never tried it in a production situation. I come from old school where every table is defined with a primary key.

So a ALTER TABLE [name] DROP PRIMARY KEY results in a long wait, and a reduction in the Index size to 900MB. WOOT! Now, in closer analysis the Primary Key is the Primary Key because it’s the Unique requirement for the table. No problem I just add a Unique Key to replace the previously dropped Primary Key. A check to review the Index Size showed a size of 2.3GB. What the!

It seems if you read the fine print of the MySQL documentation for Innodb Table Structures there is an exception clause. If you do not define a PRIMARY KEY for your table, MySQL picks the first UNIQUE index that has only NOT NULL columns as the primary key and InnoDB uses it as the clustered index.

In my situation, by adding a Unique Key this was in turn converted internally to the new Primary Key. Drat! So to the Innodb developers out there. I’d like to see a way for the internally generated key to remain in this situation, or at least provide the ability for the designer to choose this capability.

The only result is to physically create an INTEGER UNSIGNED NOT NULL AUTO_INCREMENT PRIMARY KEY column definition. This may seem like not a big thing, but the customer did not want to make any schema changes. However it was a necessity simply as the first step to get reasonable performance.

This was only the first part of the problem, solving the full table scans via creative Indexing was not possible, code changes were out of the question for an immediate fix. The real problem was the size of the innodb_buffer_pool_size. It was just too small to handle both the table data and index pages in memory. Perfmon analysis showed the machine simply when into intensive disk I/O every time any queries were run. On a Linux system with just a database and Innodb tables, it can be recommended that 70-80% of available memory can be allocated to the innodb_buffer_pool_size.

Alas this is Windows 32 bit, and their is an implied 2GB memory limit for any process, so the best one could manage in this situation was 1600MB.
The long and the short was that even with poor database design, and immediate performance improvement occurred with an optimal Primary Key and sufficient memory allocated to the correct MySQL buffers. This is only a temporary fix for a greater problem.

I’m interested to know what people consider will behold MySQL in 2007?

The announcement of “You” as Time person of the year can only considered a huge boost to the opportunities in 2007. So, in 2007 here are my 7 (in no significant order).

1. 2007 will be the year of the storage engine. We will see 5 offerings for transactional storage engines, 20+ available and practical engines for management of some form of data.
2. 2007 will see MySQL 5.1 GA (finally).
3. 2007 will see MySQL release it’s own Falcon Storage Engine (GA not until Q4 :-().
4. The MySQL Winter of Code will enable the contributions of the community to change feature development. I foresee a Bounty system from an external party or parties for MySQL Features emerging.
5. MySQL will make major press inroads to the RDBMS Big 3 of Oracle, SQL Server and IBM DB2.
6. Despite efforts of MySQL AB, major installations of MySQL 4.0 and 4.1 including large ISP’s will hamper the uptake of 5.0 and 5.1 and the de-commissioning of 4.x
7. A major country government will make an announcement to move to Open Source across servers and desktops, and MySQL will contribute to being an enterprise database offering in systems replacements as part of a longer term strategy.