I have released version 0.0.9 of Chef multipath cookbook. The cookbook now supports Pure Storage SAN among a bunch of other improvements.

Below is the list of changes and improvements in version 0.0.9 of Chef multipath cookbook:

• Added support for Pure Storage SAN
• Added test-kitchen tests
• Reimplemented the chefspec tests
• Fixed the issues reported by foodcritic

The cookbook is now tested to work with Chef 12.

To configure multipath for Pure Storage LUNs, all you need to do is set the following attribute:
node["multipath"]["storage_type"] = "purestorage"

Feel free to contribute in the form of pull requests and bug reports. The repository is available at https://github.com/ovaistariq/cookbook-multipath

Does your dataset consist of InnoDB tables with large BLOB data such that the data is stored in external BLOB pages? Was the dataset created in MySQL version 5.1 and below and without using the InnoDB plugin, or with InnoDB plugin but with MySQL version earlier than 5.1.55? If the answer to both the questions are “YES” then it could very well be that you have a hidden corruption lying around in your dataset. The only way you would be able to find out about the corruption is when you have a crash with InnoDB assertion messages similar to the following:

InnoDB: Serious error! InnoDB is trying to free page 4
InnoDB: though it is already marked as free in the tablespace!
InnoDB: The tablespace free space info is corrupt.


In this post I will summarize what the bug is and how it corrupts the dataset. If you want more details of why and how the corruption manifests itself then you can additionally read the following bug reports:
http://bugs.mysql.com/bug.php?id=55543
http://bugs.mysql.com/bug.php?id=55284
http://bugs.mysql.com/bug.php?id=55981

MySQL BLOB Corruption

The bug involves records that contain BLOBs that are stored off page on external pages. When are BLOBs stored off-page depends on the size of the blob and the row format and sometimes also depends on the size of the rows. Since we are mainly talking about older MySQL versions, so we would only be dealing with COMPACT and REDUNDANT row formats. Basically, InnoDB tries to store the entire BLOB on the same InnoDB page, but if the row size is large such that at least two rows cannot be stored on the page, then InnoDB will store the first 768 bytes from the BLOB on the page where the row is stored and the rest of the BLOB data is stored on external page. The page that contains the row then contains the pointer to the external page so that when InnoDB is reading the row it can lookup the BLOB by following the pointer.

Now coming back to the bug. The bug is caused by certain parts of the InnoDB code that cause the external page holding the BLOB data to get orphaned.
One way the page gets orphaned is when the PRIMARY key column is being updated, but the update is rolled back for some reason. Now as you know that updating the PRIMARY key column would require a delete of the old row and a creation of a new row with the new data. It would also require moving the pointer data pointing to the external BLOB page from the old row to the new row. This moving of the association between the row and the external page from old row to new row was not being done in a consistent and transaction safe way which would cause the association to get lost in case of a transaction rollback.

What was really happening can be seen as a sequence of the below events:

• a. A transaction modifies the PRIMARY key column
• b. Modification of PRIMARY key column causes the creation of a new row with the new data and old row being delete-marked
• c. The association between the old row and the external BLOB page is changed, such that the external BLOB page is now associated with the new row.
• d. The transaction is rolled back. The rollback undoes the changes, but does not change the association of the external BLOB page back to the old row.

Hence, a transaction rollback would cause the BLOB page to get orphaned and freed. Once the page is freed it can be reused by InnoDB for storing BLOB data for other rows. The important thing to note here is that the original row that we tried to modify (but rolled back the changes) still contains a pointer to the external BLOB page. The thing that is lost is the association from InnoDB’s perspective and that is why it considers the page free to be reused.

Now, this issue does not immediately cause any crashes. So you would never really know. A crash would only happen when the row above that we tried to modify (but rolled back the change) is deleted. Marko summarizes when this bug would cause a crash as follows:
“Furthermore, if your tablespace has been created and modified with an old (buggy) version of InnoDB, a BLOB page could be freed and reused for something else. InnoDB would read and deliver the overwritten contents of the BLOB page to queries. The problem would not be detected until you actually delete the row and both the original BLOB page and the reused BLOB page have been freed.”

Is there any other way to test for this kind of corruption? No, there is no way possible. Neither “CHECK TABLE” nor innochecksum validate pointers to BLOB pages in any way.
Below is an excerpt from the MySQL manual:
“CHECK TABLE surveys the index page structure, then surveys each key entry. It does not validate the key pointer to a clustered record or follow the path for BLOB pointers.”

Mitigation

So what is the safest path then? The safest thing to do is to rebuild the dataset by means of dump and reload. We mostly have slaves and secondary masters created using some form of filesystem copy, either a direct copy or such as using XtraBackup. So if a crash does happen due to this bug, since it would most likely happen after a DELETE gets executed, the crash would replicate to the slaves as well, which if created using some form of filesystem copy would crash as well. A crash of the replication hierarchy would be a disaster.

Another thing to be careful about is when running tools that would DELETE rows containing large BLOB values. For example, if you run pt-table-sync on a table with hidden corruption and pt-table-sync has to sync records then there is a chance that could cause a crash. This is because by default pt-table-sync executes REPLACE statements which are internally mapped to DELETE+UPDATE.

Conclusion

So to summarize, if your dataset was created such that it meets either of the following conditions:
a. Dataset created under MySQL version <= 5.1 without using innodb plugin, or b. dataset created under mysql version < 5.1.55 and plugin then it is a very good idea to rebuild the dump reload. bugs were only fixed in above for plugin. p>

Test Kitchen together with Vagrant is a wonderful way to test out your infrastructure deployment and orchestration code. It makes test-driven development especially easy by allowing you to test locally using virtual machines. However, those of you who do a lot of testing with Test Kitchen and Vagrant would know that waiting for tests to complete can be painfully long. This is especially true when with every test run the same packages have to be downloaded over and over again. Or when Vagrant decides to update the Virtual Box Guest Addition plugin every time you run your test suites.

Christine Draper has an excellent post which allows one to remove much of the waiting and make test runs instant. These basically involve installing two Vagrant plugins vagrant-cachier and vagrant-omnibus and disabling automatic Virtual Box Guest Addition plugin updates.

I would not detail why and how here, as details are already present in Christine’s post which I have referenced. I would rather provide you with a Vagrantfile template that can be used with Test Kitchen so that we can make it use the two plugins and disable Virtual Box Guest Addition plugin updates.

Below is the content which you will need to write to a file named Vagrantfile.erb

Vagrant.configure("2") do |c|
  c.vm.box = "<%= config[:box] %>"
  c.vm.box_url = "<%= config[:box_url] %>"

  if Vagrant.has_plugin?("vagrant-cachier")
    c.cache.auto_detect = true
    c.cache.scope = :box
  end

  if Vagrant.has_plugin?("vagrant-omnibus")
    c.omnibus.cache_packages = true
    c.omnibus.chef_version = "11.16.4"
  end

  c.vbguest.auto_update = false

<% if config[:vm_hostname] %>
  c.vm.hostname = "<%= config[:vm_hostname] %>"
<% end %>
<% if config[:guest] %>
  c.vm.guest = <%= config[:guest] %>
<% end %>
<% if config[:username] %>
  c.ssh.username = "<%= config[:username] %>"
<% end %>
<% if config[:ssh_key] %>
  c.ssh.private_key_path = "<%= config[:ssh_key] %>"
<% end %>

<% array(config[:network]).each do |opts| %>
  c.vm.network(:<%= opts[0] %>, <%= opts[1..-1].join(", ") %>)
<% end %>

  c.vm.synced_folder ".", "/vagrant", disabled: true
<% config[:synced_folders].each do |source, destination, options| %>
  c.vm.synced_folder "<%= source %>", "<%= destination %>", <%= options %>
<% end %>

  c.vm.provider :<%= config[:provider] %> do |p|
<% config[:customize].each do |key, value| %>
  <% case config[:provider] when "virtualbox" %>
    p.customize ["modifyvm", :id, "--<%= key %>", "<%= value %>"]
  <% when "rackspace", "softlayer" %>
    p.<%= key %> = "<%= value%>"
  <% when ^vmware_ %>
    <% if key="=" :memory %>
      <% unless config[:customize].include?(:memsize) %>
    p.vmx["memsize"] = "<%= value %>"
      <% end %>
    <% else %>
    p.vmx["<%= key %>"] = "<%= value %>"
    <% end %>
  <% end %>
<% end %>
  end

end

The file Vagrantfile.erb can be in the same directory as the .kitchen.yml file and can be referenced in .kitchen.yml in the “platforms” section as follows:

platforms:
  - name: centos-6.4
    driver:
      vagrantfile_erb: Vagrantfile.erb

That’s about it. Next time you test your infrastructure code, don’t forget to use the Vagrantfile.erb template. You will be pleased to see how quickly the tests finish.

Emphasis on clustering solutions comes up quite a lot when talking to customers about High Availability. The reason is because clustering is supposed to provide an easier solution for maintaining high availability and so that you do not have to rely on other tools and techniques outside of the database server.

I thought it would be good to share the gist of many of my discussions around clustering, in the form of a blog post.

People usually tend to compare MySQL NDB Cluster and Percona XtraDB Cluster but both of them really are very different solutions.

For one NDB Cluster would mean a complete rethink of how data is accessed by the application. You also get to have to deal with a storage engine that works and behaves differently from InnoDB storage engine. The key point with NDB Cluster is data partitioning between different nodes. Not all applications are built with partitioning in mind specifically. And such you would have to adapt the application to make sure that it is aware of that and can distribute the workload effectively. This may mean partitioning in such a way that a single application request does not imply having to go to each partition to fetch data. I have typically seen a lot of effort put into applications when moving from traditional InnoDB based solution to NDB based solution. Moving to NDB Cluster is a major major change and as such implies that you would probably need to rewrite parts of the application to make it work effectively.

To summarize: MySQL NDB Cluster is not a drop-in-place clustering solution.

However, Percona XtraDB Cluster, which is Galera-based clustering solution, is a drop-in-place clustering solution and it truly is. You might have to do minute changes in the application, but you can even live with not having to do any. If you are already using InnoDB storage engine, then you do not need to make any changes to the application, except may be for the fact that deadlocks happen a bit differently. Percona XtraDB Cluster provides a clustering layer over traditional MySQL server with InnoDB storage engine, such that everything is exactly the same except how replication is performed. XtraDB Cluster is a synchronous replication cluster, meaning that every transaction COMMIT implies that the transaction is replicated to every node in the cluster where a process known as certification is performed to validate the transaction that is committed and perform conflict resolution. And you get other benefits with it:

• High Availability: You can read/write to any node, when a node goes down, you can start reading/writing from a different node
• Data Consistency: You do not have to worry about data consistency in the same way as you do with regular MySQL master-slave pair
• Parallel Replication: You get true parallel replication without the restrictions that are present in MySQL 5.6
• Partitioning Protection: Partitioning protection is built inside this clustering solution

What I really like about this solution, other then the fact that this is a true drop-in-place solution, is that you do not have to rely on other pieces of software to get high availability or partitioning protection. These things are already taken care of and as such this greatly reduces the complexity of this clustering solution. Otherwise with a typical MySQL master-slave setup you have to rely on other solutions such as Pacemaker to get high availability and other related things. The other difference of course when compared to MySQL NDB Cluster is that data is not partitioned in any way, all the data is present on every node in a XtraDB Cluster.

To summarize: Percona XtraDB Cluster is a drop-in-place clustering solution.

I would suggest that you read more about Percona XtraDB Cluster here and give it a try when the next time you want to move to a clustering solution.

Each day there is probably work done to improve performance of the InnoDB storage engine and remove bottlenecks and scalability issues. Hence there was another one I wanted to highlight: Scalability issues due to tables without primary keys. This scalability issue is caused by the usage of tables without primary keys. This issue typically shows itself as contention on the InnoDB dict_sys mutex. Now the dict_sys mutex controls access to the data dictionary. This mutex is used at various important places throughout the InnoDB code and as such any contention on the dict_sys mutex is going to have a InnoDB system-wide negative affect. You can read the rest of the post here.

This is the third blog post in the series of blog posts leading up to the talk comparing the optimizer enhancements in MySQL 5.6 and MariaDB 5.5. This blog post is targeted at the join related optimizations introduced in the optimizer. These optimizations are available in both MySQL 5.6 and MariaDB 5.5, and MariaDB 5.5 has introduced some additional optimizations which we will also look at, in this post. You can read the rest of the post here.

I have written a second blog post in the series of blog posts leading up to the talk comparing the optimizer enhancements in MySQL 5.6 and MariaDB 5.5. This blog post is aimed at the optimizer enhancement Multi Range Read (MRR). Its available in both MySQL 5.6 and MariaDB 5.5

You can read the entire blog post here.

I have been working with Peter in preparation for the talk comparing the optimizer enhancements in MySQL 5.6 and MariaDB 5.5. We are taking a look at and benchmarking optimizer enhancements one by one. So in the same way this blog post is aimed at a new optimizer enhancement Index Condition Pushdown (ICP). Its available in both MySQL 5.6 and MariaDB 5.5 You can read more about this at MySQL Performance Blog here.

Overview

Profiling, analyzing and then fixing slow queries is likely the most oft-repeated part of a job of a DBA. And there are not too many tools out there that can make your life easy by providing analysis of queries with such data points that allow you to attack the right queries in the right way. One such tool that I have always found myself using is pt-query-digest(formerly known as mk-query-digest).

Now let us go through using this very nice tool.

Before We Start!

But before we start, make sure you have enabled slow query logging and set a low enough long_query_time. The correct value of long_query_time depends on your application requirements, a long_query_time of 1 second or 2 seconds might be sufficient for most of the users. Its also typical to see in many cases that you set the long_query_time to 0 for a small period of time to log all the queries.

Note that logging all queries in this fashion as opposed to the general query log, enables us to have the statistics available after the query is actually executed, while no such statistics are available for queries that are logged using the general query log.

And there might be other cases when you want to log queries taking less than 1 second of time(micro-seconds), for that you can specify a value in fractions, for example, you can specify long_query_time=0.5 to log queries taking greater than half-a-second.

Note that logging queries taking fraction of a second is not possible for versions of MySQL < 5.1, unless you use the microslow patch developed by Percona. You can follow the guide here if you are still running MySQL < 5.1 and would like to install this patch. You should also note that for versions of MySQL < 5.1 setting long_query_time=0 would actually disable the slow query logging.

Installing pt-query-digest tool (as well as other tools from Percona Toolkit) is very easy, and is explained here at this link.

Using pt-query-digest

Using pt-query-digest is pretty straight forward:

pt-query-digest /path/to/slow-query.log

Note that executing pt-query-digest can be pretty CPU and memory consuming, so ideally you should download the “slow query log” to another machine and run it there.

Analyzing pt-query-digest Output

Now let’s see what output it returns. The first part of the output is an overall summary:

# 250ms user time, 20ms system time, 17.38M rss, 53.62M vsz
# Current date: Wed Dec 28 08:16:13 2011
# Hostname: somehost.net
# Files: ./slow-query.log
# Overall: 296 total, 12 unique, 0.00 QPS, 0.00x concurrency _____________
# Time range: 2011-11-26 17:44:58 to 2011-12-27 13:01:44
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           736s      1s     23s      2s      6s      2s      1s
# Lock time            5ms       0   290us    17us   103us    43us       0
# Rows sent          8.31M       0   8.31M  28.75k  202.40 477.30k       0
# Rows examine      53.69k       0   3.51k  185.75  964.41  497.06       0
# Rows affecte          38       0       1    0.13    0.99    0.33       0
# Rows read          8.31M       0   8.31M  28.75k  202.40 477.30k       0
# Bytes sent       294.94M       0 275.07M 1020.33k  79.83k  15.63M  79.83k
# Tmp tables            16       0       4    0.05       0    0.45       0
# Tmp disk tbl           0       0       0       0       0       0       0
# Tmp tbl size       1.94M       0 496.08k   6.70k       0  56.06k       0
# Query size        36.89k      44     886  127.63  420.77  144.69   69.19

It tells you that there are a total of 296 slow queries which are actually invocations of 12 different queries. Following that there are summaries of various other data points such as the total query execution time and the average query execution time. One thing I suggest here is that, you should probably give more importance to the times/values reported in the 95% (95th percentile) column as that gives us more accurate understanding. Now, for example, from this summary you can easily see whether you need to bump up the tmp_table_size variable if you see a big “Tmp disk tbl” number, you can easily adjust the value of tmp_table_size by taking a look at the 95% column for the row dealing with “Tmp tbl size”. Pretty nifty!

Let’s analyze next part of the output produced by pt-query-digest.

# Profile
# Rank Query ID           Response time  Calls R/Call  Apdx V/M   Item
# ==== ================== ============== ===== ======= ==== ===== ========
#    1 0x92F3B1B361FB0E5B 644.9895 87.6%   244  2.6434 0.44  1.26 SELECT wp_options
#    2 0x555191621979A464  33.6349  4.6%    30  1.1212 0.65  0.03 REPLACE SELECT test.checksum test.sbtest_myisam
#    3 0x8354260420CBD34B  22.6124  3.1%     1 22.6124 0.00  0.00 SELECT customer address category

The above part of the output ranks the queries and shows the top slowest queries. As we can see here the slowest one is the SELECT wp_options, this is basically a unique way of identifying the query and simply implies that this is a SELECT query executed against the wp_options table.

Now let’s take a look at the most important part of the output:

# Query 1: 0.00 QPS, 0.00x concurrency, ID 0x92F3B1B361FB0E5B at byte 119442
# This item is included in the report because it matches --limit.
# Scores: Apdex = 0.44 [1.0], V/M = 1.26
# Query_time sparkline: |      ^ |
# Time range: 2011-12-08 17:48:20 to 2011-12-27 13:01:44
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         82     244
# Exec time     87    645s      1s     10s      3s      6s      2s      1s
# Lock time     37     2ms       0   201us     8us    60us    30us       0
# Rows sent      0   3.40k       0     211   14.28  202.40   51.53       0
# Rows examine   7   4.01k       0     252   16.84  234.30   60.55       0
# Rows affecte   0       0       0       0       0       0       0       0
# Rows read      0   3.40k       0     211   14.28  202.40   51.53       0
# Bytes sent     6  19.03M  41.35k  83.95k  79.88k  79.83k   6.92k  79.83k
# Tmp tables     0       0       0       0       0       0       0       0
# Tmp disk tbl   0       0       0       0       0       0       0       0
# Tmp tbl size   0       0       0       0       0       0       0       0
# Query size    45  16.92k      71      71      71      71       0      71
# String:
# Databases    wp_blog_one (154/63%), wp_blog_tw... (81/33%)... 1 more
# Hosts
# InnoDB trxID 7F1910 (1/0%), 7F3860 (1/0%), 7F9F74 (1/0%)... 14 more
# Last errno   0
# Users        wp_blog_one (154/63%), wp_blog_two (81/33%)... 1 more
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `wp_blog_two` LIKE 'wp_options'\G
#    SHOW CREATE TABLE `wp_blog_two`.`wp_options`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT option_name, option_value FROM wp_options WHERE autoload = 'yes'\G

This is the actual part of the output dealing with analysis of the most slowest query ranked #1. The first row in the table above shows the Count of number of times this query was executed. Now let’s take a look at the values in the 95% column, we can clearly see that this query is taking up a lot of execution time (6s) and is sending a lot of rows (202) and a lot of data (79.83k). The “Databases” section of the output also shows the name of the databases where this query was executed. Next the “Query_time distribution” section shows how this query times, which you can see lies in the range 1s to 10s all the time. The “Tables” section lists the queries that you can use to gather more data about the underlying tables involved and the query execution plan used by MySQL.
The end result might be that you end up limiting the number of results returned by the query, by using a LIMIT clause or by filtering based on the option_name column.

Let’s analyze another slow query, this time query ranked #3 by pt-query-digest.

# Query 3: 0 QPS, 0x concurrency, ID 0x8354260420CBD34B at byte 132619 ___
# This item is included in the report because it matches --limit.
# Scores: Apdex = 0.00 [1.0]*, V/M = 0.00
# Query_time sparkline: |       ^|
# Time range: all events occurred at 2011-12-23 17:07:16
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       1
# Exec time      3     23s     23s     23s     23s     23s       0     23s
# Lock time      1   101us   101us   101us   101us   101us       0   101us
# Rows sent     99   8.31M   8.31M   8.31M   8.31M   8.31M       0   8.31M
# Rows examine   0      24      24      24      24      24       0      24
# Rows affecte   0       0       0       0       0       0       0       0
# Rows read     99   8.31M   8.31M   8.31M   8.31M   8.31M       0   8.31M
# Bytes sent    93 275.07M 275.07M 275.07M 275.07M 275.07M       0 275.07M
# Tmp tables     0       0       0       0       0       0       0       0
# Tmp disk tbl   0       0       0       0       0       0       0       0
# Tmp tbl size   0       0       0       0       0       0       0       0
# Query size     0      92      92      92      92      92       0      92
# String:
# Databases    another_db
# Hosts
# InnoDB trxID 83E808
# Last errno   0
# Users        another_db
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `another_db` LIKE 'customer'\G
#    SHOW CREATE TABLE `another_db`.`customer`\G
#    SHOW TABLE STATUS FROM `another_db` LIKE 'address'\G
#    SHOW CREATE TABLE `another_db`.`address`\G
#    SHOW TABLE STATUS FROM `another_db` LIKE 'category'\G
#    SHOW CREATE TABLE `another_db`.`category`\G
# EXPLAIN /*!50100 PARTITIONS*/
select customer.store_id, address.address, category.name
  from customer, address, category\G

Let’s again take a look at the 95% column in the above output. And you can clearly see that the problem with this query is that its reading and sending far too many rows (8.31M) and sending far too much data (275M). Going down quickly to the “Tables” section, you can see why that is happening: “Three tables joined without a join condition meaning a cartesian product of all the rows in all the three tables”. See how easily you could pin-point the cause of slowness.
This query was actually executed on a demo of a MySQL Web Client running on one of the MySQL servers managed by me, providing me with good reason to turn on safe-updates option.

Gather Even More Stats with some extra love from Percona Server!

My colleagues at Percona have built in much more verbosity to what is output in the slow query log, which would give you even more insight into what is actually going on behind the scene during the execution of a particular slow query. This is through the edition of a new variable available in Percona Server 5.1 and above called log_slow_verbosity. You can read more about this variable and some other diagnostics added to the Percona server from this link. The variable log_slow_verbosity can have the values ‘microtime’, ‘query_plan’, ‘innodb’ and ‘full’. Let’s turn on log_slow_verbosity as follows:

set session log_slow_verbosity='microtime,query_plan,innodb';

And see how verbose the new entry in slow log is:

# Time: 111228 11:52:30
# User@Host: root[root] @ localhost []
# Thread_id: 57  Schema: mywebsql_demo  Last_errno: 0  Killed: 0
# Query_time: 204.981516  Lock_time: 0.000133  Rows_sent: 10000  Rows_examined: 8721904  Rows_affected: 0  Rows_read: 10000
# Bytes_sent: 164952  Tmp_tables: 2  Tmp_disk_tables: 1  Tmp_table_sizes: 1995142008
# InnoDB_trx_id: 856C30
# QC_Hit: No  Full_scan: Yes  Full_join: Yes  Tmp_table: Yes  Tmp_table_on_disk: Yes
# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 662
#   InnoDB_IO_r_ops: 1  InnoDB_IO_r_bytes: 16384  InnoDB_IO_r_wait: 0.034391
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 11
SET timestamp=1325073150;
select customer.store_id, address.address, category.name   from customer, address, (select * from category) as category order by customer.store_id limit 10000;

See how much more information the slow query log has now, it reports everything from InnoDB stats to on disk filesort was needed for the query, etc. Now you can clearly see this is much much more helpful then the regular slow query statistics reported by the vanilla MySQL.

Conclusion

The only conclusion, I can make out is “Get yourself Percona Server, turn on log_slow_verbosity and start using pt-query-digest”, your job of identifying bottleneck queries will be all the more simpler then.