Dec
28
2016
--

Quickly Troubleshoot Metadata Locks in MySQL 5.7

Metadata Locks

Metadata LocksIn a previous article, Ovais demonstrated how a DDL can render a table blocked from new queries. In another article, Valerii introduced performance_schema.metadata_locks, which is available in MySQL 5.7 and exposes metadata lock details. Given this information, here’s a quick way to troubleshoot metadata locks by creating a stored procedure that can:

  • Find out which thread(s) have the metadata lock
  • Determine which thread has been waiting for it the longest
  • Find other threads waiting for the metadata lock

Setting up instrumentation

First, you need to enable instrumentation for metadata locks:

UPDATE performance_schema.setup_instruments SET ENABLED = 'YES' WHERE NAME = 'wait/lock/metadata/sql/mdl';

Second, you need to add this stored procedure:

USE test;
DROP PROCEDURE IF EXISTS procShowMetadataLockSummary;
delimiter //
CREATE PROCEDURE procShowMetadataLockSummary()
BEGIN
	DECLARE table_schema VARCHAR(64);
    DECLARE table_name VARCHAR(64);
    DECLARE id bigint;
    DECLARE time bigint;
    DECLARE info longtext;
	DECLARE curMdlCount INT DEFAULT 0;
    DECLARE curMdlCtr INT DEFAULT 0;
	DECLARE curMdl CURSOR FOR SELECT * FROM tmp_blocked_metadata;
	DROP TEMPORARY TABLE IF EXISTS tmp_blocked_metadata;
	CREATE TEMPORARY TABLE IF NOT EXISTS tmp_blocked_metadata (
       table_schema varchar(64),
       table_name varchar(64),
       id bigint,
	   time bigint,
       info longtext,
       PRIMARY KEY(table_schema, table_name)
    );
    REPLACE tmp_blocked_metadata(table_schema,table_name,id,time,info) SELECT mdl.OBJECT_SCHEMA, mdl.OBJECT_NAME, t.PROCESSLIST_ID, t.PROCESSLIST_TIME, t.PROCESSLIST_INFO FROM performance_schema.metadata_locks mdl JOIN performance_schema.threads t ON mdl.OWNER_THREAD_ID = t.THREAD_ID WHERE mdl.LOCK_STATUS='PENDING' and mdl.LOCK_TYPE='EXCLUSIVE' ORDER BY mdl.OBJECT_SCHEMA,mdl.OBJECT_NAME,t.PROCESSLIST_TIME ASC;
    OPEN curMdl;
    SET curMdlCount = (SELECT FOUND_ROWS());
    WHILE (curMdlCtr < curMdlCount)
    DO
      FETCH curMdl INTO table_schema, table_name, id, time, info;
      SELECT CONCAT_WS(' ','PID',t.PROCESSLIST_ID,'has metadata lock on', CONCAT(mdl.OBJECT_SCHEMA,'.',mdl.OBJECT_NAME), 'with current state', CONCAT_WS('','[',t.PROCESSLIST_STATE,']'), 'for', t.PROCESSLIST_TIME, 'seconds and is currently running', CONCAT_WS('',"[",t.PROCESSLIST_INFO,"]")) AS 'Process(es) that have the metadata lock' FROM performance_schema.metadata_locks mdl JOIN performance_schema.threads t ON t.THREAD_ID = mdl.OWNER_THREAD_ID WHERE mdl.LOCK_STATUS='GRANTED' AND mdl.OBJECT_SCHEMA = table_schema and mdl.OBJECT_NAME = table_name AND mdl.OWNER_THREAD_ID NOT IN(SELECT mdl2.OWNER_THREAD_ID FROM performance_schema.metadata_locks mdl2 WHERE mdl2.LOCK_STATUS='PENDING' AND mdl.OBJECT_SCHEMA = mdl2.OBJECT_SCHEMA and mdl.OBJECT_NAME = mdl2.OBJECT_NAME);
      SELECT CONCAT_WS(' ','PID', id, 'has been waiting for metadata lock on',CONCAT(table_schema,'.', table_name),'for', time, 'seconds to execute', CONCAT_WS('','[',info,']')) AS 'Oldest process waiting for metadata lock';
      SET curMdlCtr = curMdlCtr + 1;
	  SELECT CONCAT_WS(' ','PID', t.PROCESSLIST_ID, 'has been waiting for metadata lock on',CONCAT(table_schema,'.', table_name),'for', t.PROCESSLIST_TIME, 'seconds to execute', CONCAT_WS('','[',t.PROCESSLIST_INFO,']')) AS 'Other queries waiting for metadata lock' FROM performance_schema.metadata_locks mdl JOIN performance_schema.threads t ON t.THREAD_ID = mdl.OWNER_THREAD_ID WHERE mdl.LOCK_STATUS='PENDING' AND mdl.OBJECT_SCHEMA = table_schema and mdl.OBJECT_NAME = table_name AND mdl.OWNER_THREAD_ID AND t.PROCESSLIST_ID <> id ;
	END WHILE;
    CLOSE curMdl;
END//
delimiter ;

Testing

Now, let’s call the procedure to see if there are threads waiting for metadata locks:

mysql> CALL test.procShowMetadataLockSummary();
+----------------------------------------------------------------------------------------------------------------+
| Process(es) that have the metadata lock                                                                        |
+----------------------------------------------------------------------------------------------------------------+
| PID 10 has metadata lock on sbtest.sbtest with current state [] since 274 seconds and is currently running []  |
| PID 403 has metadata lock on sbtest.sbtest with current state [] since 291 seconds and is currently running [] |
+----------------------------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)
+------------------------------------------------------------------------------------------------------------------------+
| Oldest process waiting for metadata lock                                                                               |
+------------------------------------------------------------------------------------------------------------------------+
| PID 1264 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [truncate table sbtest.sbtest] |
+------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
+---------------------------------------------------------------------------------------------------------------------------+
| Other queries waiting for metadata lock                                                                                   |
+---------------------------------------------------------------------------------------------------------------------------+
| PID 1269 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] |
| PID 1270 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] |
| PID 1271 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] |
| PID 1272 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] |
| PID 1273 has been waiting for metadata lock on sbtest.sbtest for 264 seconds to execute [SELECT c from sbtest where id=?] |
+---------------------------------------------------------------------------------------------------------------------------+
5 rows in set (0.00 sec)

So, as you can see above, you have several choices. You could (a) do nothing and wait for threads 10 and 403 to complete and then thread 1264 can get the lock.

If you can’t wait, you can (b) kill the threads that have the metadata lock so that the TRUNCATE TABLE in thread 1264 can get the lock. Although, before you decide to kill threads 10 and 403, you should check

SHOW ENGINE INNODB STATUS

 to see if the undo log entries for those threads are high. If they are, rolling back these transactions might take a long time.

Lastly, you can instead (c) kill the DDL thread 1264 to free up other queries. You should then reschedule the DDL to run during offpeak hours.

Happy metadata lock hunting!

Feb
10
2016
--

Estimating potential for MySQL 5.7 parallel replication

parallel replication

parallel replicationUnlike MySQL 5.6, where parallel replication can only be used when replicas have several schemas, MySQL 5.7 replicas can read binlog group commit information coming from the master to replicate transactions in parallel even when a single schema is used. Now the question is: how many replication threads should you use?

A simple benchmark

Let’s assume we have one master and three slaves, all running MySQL 5.7.

One slave is using regular single-threaded replication (the control slave in the graph below), one is using 20 parallel workers (MTS 20 workers) and the last one is using 100 parallel workers (MTS 100 workers).

As a reminder, here is the settings that need to be adjusted for 5.7 parallel replication:

slave_parallel_type = LOGICAL_CLOCK
slave_parallel_workers = 20

GTID replication is also highly recommended, if you don’t want to face annoying issues.

Now let’s run a simple sysbench workload, inserting records in 25 separate tables in the same database with 100 concurrent threads:

sysbench --mysql-user=root --mysql-db=db1 --test=/usr/share/doc/sysbench/tests/db/insert.lua --max-requests=500000 --num-threads=100 --oltp-tables-count=25 run

Because we’re using 100 concurrent threads on the master, we can expect that some parallelization is possible. This means that if we see replication lag with the control slave, we’ll probably see less lag with the 20-worker slave and even less with the 100-worker slave.

This is not exactly what we get:

lag_all

Parallel replication is indeed useful, but the 100-worker slave doesn’t provide any benefits compared to the 20-worker slave. Replication lag is even slightly worse.

What happened?

Some instrumentation with performance_schema

To have a better understanding of how efficiently the parallel replication threads are used, let’s enable some instrumentation on slaves (in other words, recording executed transactions):

UPDATE performance_schema.setup_consumers SET ENABLED = 'YES'
WHERE NAME LIKE 'events_transactions%';
UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES'
WHERE NAME = 'transaction';

For better readability of the results, let’s create a new view (tracking how many transactions are executed by each replication thread):

CREATE VIEW mts_summary_trx AS select performance_schema.events_transactions_summary_by_thread_by_event_name.THREAD_ID AS THREAD_ID,
performance_schema.events_transactions_summary_by_thread_by_event_name.COUNT_STAR AS COUNT_STAR
from performance_schema.events_transactions_summary_by_thread_by_event_name
where performance_schema.events_transactions_summary_by_thread_by_event_name.THREAD_ID
in (select performance_schema.replication_applier_status_by_worker.THREAD_ID
  from performance_schema.replication_applier_status_by_worker);

Now, after running sysbench again, let’s do some math to see how often each replication thread was run:

SELECT SUM(count_star) FROM mts_summary_trx INTO @total;
SELECT 100*(COUNT_STAR/@total) AS PCT_USAGE FROM mts_summary_trx;
+-----------+
| PCT_USAGE |
+-----------+
|   39.5845 |
|   31.4046 |
|   12.0119 |
|    5.9081 |
|    3.0375 |
|    1.6527 |
|    1.0550 |
|    0.7576 |
|    0.6089 |
|    0.5208 |
|    0.4642 |
|    0.4157 |
|    0.3832 |
|    0.3682 |
|    0.3408 |
|    0.3247 |
|    0.3076 |
|    0.2925 |
|    0.2866 |
|    0.2749 |
+-----------+

We can see that the workload has a limited potential for parallelism – therefore, it’s not worth configuring more than 3-4 replication threads.

The slight performance degradation with 100 replication threads is probably due to the overhead of the coordinator thread.

Conclusion

Estimating the optimal number of replication threads with MySQL 5.7 parallel replication is quite difficult if your just guessing. The performance_schema provides a simple way to understand how the workload is handled by the replication threads.

It also allows you to see if tuning binlog_group_commit_sync_delay provides more throughput on slaves without too much impact on the master’s performance.

Dec
18
2015
--

Performance Schema: Measure Multi-Threaded Slave Activity

performance schemaPerformance Schema

In many types of database workloads, using a multi-threaded slave from 5.6+ helps improve replication performance. I’ve had a number of users enable this feature, but have not seen anyone ask how each thread is performing. Here’s a quick way with Performance_Schema to measure the amount of multi-threaded slave activity on each thread (after you have already configured MTS on your slave of course ).

First, we need to enable the 

statements

 instruments:

slave1> UPDATE setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE 'events_statements_%';
Query OK, 2 rows affected (0.00 sec)
Rows matched: 3  Changed: 2  Warnings: 0

Next, let’s find the

THREAD_ID

 for our slave workers:

slave1> SELECT THREAD_ID, NAME FROM threads WHERE NAME LIKE '%worker';
+-----------+-------------------------+
| THREAD_ID | NAME                    |
+-----------+-------------------------+
|        28 | thread/sql/slave_worker |
|        29 | thread/sql/slave_worker |
|        30 | thread/sql/slave_worker |
|        31 | thread/sql/slave_worker |
+-----------+-------------------------+
4 rows in set (0.00 sec)

And then we capture measurements:

slave1> SELECT THREAD_ID, EVENT_NAME, COUNT_STAR FROM events_statements_summary_by_thread_by_event_name WHERE THREAD_ID IN (28,29,30,31) AND COUNT_STAR > 0;
+-----------+----------------------+------------+
| THREAD_ID | EVENT_NAME           | COUNT_STAR |
+-----------+----------------------+------------+
|        28 | statement/sql/update |         48 |
|        28 | statement/sql/insert |         24 |
|        28 | statement/sql/delete |         24 |
|        28 | statement/sql/begin  |         24 |
|        29 | statement/sql/update |         68 |
|        29 | statement/sql/insert |         34 |
|        29 | statement/sql/delete |         34 |
|        29 | statement/sql/begin  |         34 |
|        30 | statement/sql/update |       1864 |
|        30 | statement/sql/insert |        932 |
|        30 | statement/sql/delete |        932 |
|        30 | statement/sql/begin  |        932 |
|        31 | statement/sql/update |      40320 |
|        31 | statement/sql/insert |      20160 |
|        31 | statement/sql/delete |      20160 |
|        31 | statement/sql/begin  |      20160 |
+-----------+----------------------+------------+
16 rows in set (0.01 sec)

As you can see above, one of the multi-threadedthreads is doing more work compared to the other three. This is a sysbench on the master in the database doing

--trx-rate=10

, compared to the other three which are only doing 

--trx-rate=2|5

.

Below is another example, this time including the event times. With a slightly modified sysbench test, I’ve designed the tests to send large updates but one with a low transaction rate, another with a high transaction rate, and the rest in between. You can see specifically in threads 32 and 34, that the former is performing a lower amount of

UPDATES

, but spending more time per event.

slave1> SELECT THREAD_ID, EVENT_NAME, COUNT_STAR,
    ->   SUM_TIMER_WAIT/1000000 AS SUM_TIMER_WAIT_MS,
    ->   (SUM_TIMER_WAIT/COUNT_STAR)/1000000 AS AVG_TIME_MS
    -> FROM events_statements_summary_by_thread_by_event_name
    -> WHERE THREAD_ID IN (31,32,33,34) AND COUNT_STAR > 0;
+-----------+----------------------+------------+-------------------+--------------+
| THREAD_ID | EVENT_NAME           | COUNT_STAR | SUM_TIMER_WAIT_MS | AVG_TIME_MS  |
+-----------+----------------------+------------+-------------------+--------------+
|        31 | statement/sql/update |          3 |          403.9690 | 134.65633333 |
|        31 | statement/sql/insert |          1 |           91.5340 |  91.53400000 |
|        31 | statement/sql/delete |          1 |           75.9540 |  75.95400000 |
|        31 | statement/sql/begin  |          1 |           11.6800 |  11.68000000 |
|        32 | statement/sql/update |         75 |        25298.5090 | 337.31345333 |
|        32 | statement/sql/insert |         25 |         2221.1410 |  88.84564000 |
|        32 | statement/sql/delete |         25 |         2187.8970 |  87.51588000 |
|        32 | statement/sql/begin  |         25 |          321.0220 |  12.84088000 |
|        33 | statement/sql/update |       4728 |      1008736.6000 | 213.35376481 |
|        33 | statement/sql/insert |       1576 |       138815.0570 |  88.08061992 |
|        33 | statement/sql/delete |       1576 |       136161.9060 |  86.39714848 |
|        33 | statement/sql/begin  |       1576 |        20498.2300 |  13.00649112 |
|        34 | statement/sql/update |      70668 |     12304784.2380 | 174.12101995 |
|        34 | statement/sql/insert |      23556 |      2083454.5350 |  88.44687277 |
|        34 | statement/sql/delete |      23556 |      2041202.7690 |  86.65319957 |
|        34 | statement/sql/begin  |      23556 |       303710.4860 |  12.89312642 |
+-----------+----------------------+------------+-------------------+--------------+
16 rows in set (0.00 sec)

Exploring a bit further, one thing I noticed is that when using

binlog_format=ROW

  for replication, you will only see the 

BEGIN

  events instrumented from

performance_schema

. I think this is a bug so I reported it here.

slave1> SELECT THREAD_ID, EVENT_NAME, COUNT_STAR,
    ->   SUM_TIMER_WAIT/1000000 AS SUM_TIMER_WAIT_MS,
    ->   (SUM_TIMER_WAIT/COUNT_STAR)/1000000 AS AVG_TIME_MS
    -> FROM events_statements_summary_by_thread_by_event_name
    -> WHERE THREAD_ID IN (40,41,42,43) AND COUNT_STAR > 0;
+-----------+---------------------+------------+-------------------+-------------+
| THREAD_ID | EVENT_NAME          | COUNT_STAR | SUM_TIMER_WAIT_MS | AVG_TIME_MS |
+-----------+---------------------+------------+-------------------+-------------+
|        40 | statement/sql/begin |         16 |          258.6500 | 16.16562500 |
|        41 | statement/sql/begin |         91 |         1526.4320 | 16.77397802 |
|        42 | statement/sql/begin |        589 |        10131.4500 | 17.20110357 |
|        43 | statement/sql/begin |       5022 |        85584.0250 | 17.04182099 |
+-----------+---------------------+------------+-------------------+-------------+
4 rows in set (0.01 sec)

With MySQL 5.7, MTS has an additional improvement with how parallel replication is applied. By default, transactions are applied in parallel per database. With the new

slave_parallel_type

 feature, another option called

LOGICAL_CLOCK

  is introduced that allows parallelization intra-database as well. I did some small tests below, with same workload as above. First with the default

DATABASE

 type:

+-----------+----------------------+------------+-------------------+--------------+
| THREAD_ID | EVENT_NAME           | COUNT_STAR | SUM_TIMER_WAIT_MS | AVG_TIME_MS  |
+-----------+----------------------+------------+-------------------+--------------+
|        65 | statement/sql/update |         51 |         9974.1310 | 195.57119608 |
|        65 | statement/sql/insert |         17 |         2037.7080 | 119.86517647 |
|        65 | statement/sql/delete |         17 |         2144.4800 | 126.14588235 |
|        65 | statement/sql/begin  |         17 |          293.0650 |  17.23911765 |
|        66 | statement/sql/update |        255 |        67131.4980 | 263.26077647 |
|        66 | statement/sql/insert |         85 |         9629.5520 | 113.28884706 |
|        66 | statement/sql/delete |         85 |         9854.2920 | 115.93284706 |
|        66 | statement/sql/begin  |         85 |         1405.0200 |  16.52964706 |
|        67 | statement/sql/update |       1215 |       344712.6330 | 283.71410123 |
|        67 | statement/sql/insert |        405 |        48000.0110 | 118.51854568 |
|        67 | statement/sql/delete |        405 |        53222.3010 | 131.41308889 |
|        67 | statement/sql/begin  |        405 |         6836.9070 |  16.88125185 |
|        68 | statement/sql/update |       5943 |      1820669.3290 | 306.35526317 |
|        68 | statement/sql/insert |       1981 |       241513.1400 | 121.91476022 |
|        68 | statement/sql/delete |       1981 |       245022.2450 | 123.68614084 |
|        68 | statement/sql/begin  |       1981 |        32978.3390 |  16.64731903 |
+-----------+----------------------+------------+-------------------+--------------+

And then with

LOGICAL_CLOCK

:

+-----------+----------------------+------------+-------------------+--------------+
| THREAD_ID | EVENT_NAME           | COUNT_STAR | SUM_TIMER_WAIT_MS | AVG_TIME_MS  |
+-----------+----------------------+------------+-------------------+--------------+
|        59 | statement/sql/update |       9486 |      2667681.7170 | 281.22303574 |
|        59 | statement/sql/insert |       3162 |       376350.1650 | 119.02282258 |
|        59 | statement/sql/delete |       3162 |       388606.5460 | 122.89897090 |
|        59 | statement/sql/begin  |       3162 |        53988.2600 |  17.07408602 |
|        60 | statement/sql/update |        903 |       362853.2080 | 401.83079513 |
|        60 | statement/sql/insert |        301 |        36507.3090 | 121.28674086 |
|        60 | statement/sql/delete |        301 |        37437.2550 | 124.37626246 |
|        60 | statement/sql/begin  |        301 |         5210.4110 |  17.31033555 |
|        61 | statement/sql/update |         42 |        23394.0330 | 557.00078571 |
|        61 | statement/sql/insert |         14 |         1671.5900 | 119.39928571 |
|        61 | statement/sql/delete |         14 |         1720.1230 | 122.86592857 |
|        61 | statement/sql/begin  |         14 |          246.1490 |  17.58207143 |
+-----------+----------------------+------------+-------------------+--------------+

With

LOGICAL_LOCK

  and

slave_preserve_commit_order

  enabled:

+-----------+----------------------+------------+-------------------+--------------+
| THREAD_ID | EVENT_NAME           | COUNT_STAR | SUM_TIMER_WAIT_MS | AVG_TIME_MS  |
+-----------+----------------------+------------+-------------------+--------------+
|        71 | statement/sql/update |       8097 |      2216461.7170 | 273.73863369 |
|        71 | statement/sql/insert |       2699 |       322933.1620 | 119.64918933 |
|        71 | statement/sql/delete |       2699 |       326944.2380 | 121.13532345 |
|        71 | statement/sql/begin  |       2699 |        45860.5720 |  16.99169026 |
|        72 | statement/sql/update |        807 |       256668.2730 | 318.05238290 |
|        72 | statement/sql/insert |        269 |        32952.5570 | 122.50021190 |
|        72 | statement/sql/delete |        269 |        33346.3060 | 123.96396283 |
|        72 | statement/sql/begin  |        269 |         4650.1010 |  17.28662082 |
|        73 | statement/sql/update |         33 |         6823.1170 | 206.76112121 |
|        73 | statement/sql/insert |         11 |         1512.5810 | 137.50736364 |
|        73 | statement/sql/delete |         11 |         1593.5790 | 144.87081818 |
|        73 | statement/sql/begin  |         11 |          188.3910 |  17.12645455 |
+-----------+----------------------+------------+-------------------+--------------+

Combining the 

INSERT

,

UPDATE

 and

DELETE

 counts from these 3 tests,

LOGICAL_CLOCK

  tops with around 17k events within 120 seconds of the same workload. The 

DATABASE

  type was the slowest, recording only about 12k events committed on the slave.

Lastly, with MySQL 5.7 a new instrument has been added and enabled for metrics to be collected. You can also measure the per-transaction rate instead of per event class.

slave1> UPDATE setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE 'vents_transactions%';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 0  Changed: 0  Warnings: 0
slave1> UPDATE setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME = 'transaction';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

And a quick measurement:

slave1> SELECT THREAD_ID, EVENT_NAME, COUNT_STAR,
    ->   SUM_TIMER_WAIT/1000000 AS SUM_TIMER_WAIT_MS,
    ->   (SUM_TIMER_WAIT/COUNT_STAR)/1000000 AS AVG_TIME_MS
    -> FROM events_transactions_summary_by_thread_by_event_name
    -> WHERE THREAD_ID IN (
    ->     SELECT THREAD_ID FROM replication_applier_status_by_worker
    -> ) AND COUNT_STAR > 0;
+-----------+-------------+------------+-------------------+----------------+
| THREAD_ID | EVENT_NAME  | COUNT_STAR | SUM_TIMER_WAIT_MS | AVG_TIME_MS    |
+-----------+-------------+------------+-------------------+----------------+
|        71 | transaction |       4849 |     50323942.6710 | 10378.21049103 |
|        72 | transaction |        487 |      6421399.4580 | 13185.62517043 |
|        73 | transaction |         17 |       319024.9280 | 18766.17223529 |
+-----------+-------------+------------+-------------------+----------------+
3 rows in set (0.00 sec)

Of course, not only statement events and transactions can be measured – you can also measure wait times and stages as well. Happy instrumenting!

The post Performance Schema: Measure Multi-Threaded Slave Activity appeared first on MySQL Performance Blog.

Jun
01
2015
--

New PERFORMANCE_SCHEMA defaults in MySQL 5.7.7

I thought it was worth a moment to reiterate on the new Performance Schema related defaults that MySQL 5.7.7 brings to the table, for various reasons.

For one, most of you might have noticed that profiling was marked as deprecated in MySQL 5.6.7. So it is expected that you invest into learning more about Performance Schema (and Mark’s sys schema!).

Second, there are lots of virtual environments and appliances out there running Community Edition MySQL where Performance Schema can be a useful tool for analyzing performance. Thus, expect to see more articles about using PERFORMANCE_SCHEMA and SYS_SCHEMA from us!

Third, we have more and more junior readers who might benefit from light reads such as this. :)

The new defaults that I wanted to highlight are mentioned in the MySQL 5.7.7 release notes:
– The MySQL sys schema is now installed by default during data directory installation.
– The events_statements_history and events_transactions_history consumers now are enabled by default.

Note that if you are upgrading from an earlier version of MySQL to 5.7.7 to get these goodies you will need to run mysql_upgrade and restart the database for the above changes to take effect.

So what do these mean?

If you haven’t had a chance to dig into PERFORMANCE_SCHEMA, check out the quick start guide here. PERFORMANCE_SCHEMA is a nify tool (implemented as a union of a storage engine and a schema in MySQL) to monitor MySQL server execution at a low level, with a focus on performance metrics. It monitors for events that have been “instrumented”, such as function calls, OS wait times, synchronization calls, etc. With performance nomenclature “instruments” are essentially “probes”. The events that the instruments generate can be processed by consumers. Note that not all instruments or consumers are enabled by default.

Some would say that the structure of PERFORMANCE_SCHEMA may be complex and may not be very DBA-friendly. This is what led to the birth of SYS_SCHEMA. For those who are not familiar with Mark Leith’s SYS_SCHEMA and prefer TL;DR – it provides human friendly views, functions and procedures that can help you analyze database usage using PERFORMANCE_SCHEMA. If you haven’t had a chance to check it out yet you might want to read Miguel’s article on using the sys schema or Alexander Rubin’s article about using it in multitenant environments and give it a spin!

I welcome the fact that events_statements_history and events_transactions_history consumers are enabled by default in MySQL 5.7.7 as it means that we get some handy performance details available to us out of the box in vanilla MySQL. Note that these are per-thread tables and by default the history length (the length of the number of entries present; more on those variables here) is automatically sized, thus you may need to increase them.

What details do you get off the bat with them?

Consider the following example:

mysql> select * from performance_schema.events_statements_history where event_id=353G
*************************** 1. row ***************************
              THREAD_ID: 20
               EVENT_ID: 353
           END_EVENT_ID: 456
             EVENT_NAME: statement/sql/select
                 SOURCE: mysqld.cc:963
            TIMER_START: 1818042501405000
              TIMER_END: 1818043715449000
             TIMER_WAIT: 1214044000
              LOCK_TIME: 67000000
               SQL_TEXT: select * from imdb.title limit 100
                 DIGEST: ec93c38ab021107c2160259ddee31faa
            DIGEST_TEXT: SELECT * FROM `imdb` . `title` LIMIT ?
         CURRENT_SCHEMA: performance_schema
            OBJECT_TYPE: NULL
          OBJECT_SCHEMA: NULL
            OBJECT_NAME: NULL
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
      RETURNED_SQLSTATE: NULL
           MESSAGE_TEXT: NULL
                 ERRORS: 0
               WARNINGS: 0
          ROWS_AFFECTED: 0
              ROWS_SENT: 100
          ROWS_EXAMINED: 100
CREATED_TMP_DISK_TABLES: 0
     CREATED_TMP_TABLES: 0
       SELECT_FULL_JOIN: 0
 SELECT_FULL_RANGE_JOIN: 0
           SELECT_RANGE: 0
     SELECT_RANGE_CHECK: 0
            SELECT_SCAN: 1
      SORT_MERGE_PASSES: 0
             SORT_RANGE: 0
              SORT_ROWS: 0
              SORT_SCAN: 0
          NO_INDEX_USED: 1
     NO_GOOD_INDEX_USED: 0
       NESTING_EVENT_ID: NULL
     NESTING_EVENT_TYPE: NULL
1 row in set (0.00 sec)

As you can see from above you get similar data that you are used to seeing from EXPLAINs and slow query logs, such as query run time, locking time, rows sent/examined, etc. For instance, in above output my query obtained about a 100 rows (lines 26-27), avoided creating temp tables (lines 28-29) and didn’t have to sort (lines 36-38) and no index was used (line 39) and it ran for about 121 ms (TIMER_END-TIMER_START). The list of details provided is not as abundant as it could be but I imagine that with newer releases the list may grow.

If you want to read on and are curious about how to use Performance Schema for profiling check out Jervin’s great article here!

The post New PERFORMANCE_SCHEMA defaults in MySQL 5.7.7 appeared first on MySQL Performance Blog.

Jan
23
2015
--

Using Percona Cloud Tools to solve real-world MySQL problems

For months when speaking with customers I have been positioning Percona Cloud Tools (PCT) as a valuable tool for the DBA/Developer/SysAdmin but only recently have I truly been able to harness the data and make a technical recommendation to a customer that I feel would have been very difficult to accomplish otherwise.

Using Percona Cloud Tools to solve real-world MySQL problemsLet me provide some background: I was tasked with performing a Performance Audit for one of our customers (Performance Audits are extremely popular as they allow you to have a MySQL Expert confirm or reveal challenges within your MySQL environment and make your database run faster!) and as part of our conversation we discussed and agreed to install Percona Cloud Tools. We let the site run for a few days, and then I started my audit. What I noticed was that at regular intervals there was often a CPU spike, along with a corresponding drop in Queries Per Second (QPS), but that lasted only for a few seconds. We decided that further investigation was warranted as the customer was concerned the spikes impacted their users’ experience with the application.

Here are the tasks that Percona Cloud Tools made easy while I worked to identify the source of the CPU spike and QPS drop:

  1. Per-second granularity data capture of PCT allowed me to identify how significant the spike and QPS actually were – if I was looking at the 1 minute or higher average values (such as Cacti would provide) I probably wouldn’t have been able to detect the spike or stall as clearly in the first place, it would have been lost in the average. In the case of PCT the current graphs group at the 1 minute range but you have the ability to view the min and max values during this 1 minute range since they are the true highest and lowest observed 1s intervals during the 1 minute group.
  2. Ability for all graphs to maintain the same resolution time allowed me to zero-in on the problematic time period and then quickly look across all graphs for corresponding deflections. This analysis led me to discover a significant spike in InnoDB disk reads.
  3. Ability to use the Query Analytics functionality to zoom-in again on the problematic query. By adjusting Query Analytics to an appropriate time period narrowed down the range of unique queries that could be considered the cause. This task in my opinion is the best part of using PCT.
  4. Query Analytics allowed me to view the Rows Examined in Total for each query based on just this shortened interval. I then tagged those that had higher than 10k Rows Examined (arbitrary but most queries for this customer seemed to fall below this) so that I could then review in real-time with the customer before making a decision on what to do next. We can only view this sort of information by leveraging the slow query log – this data is not available via Performance_Schema or via network sniffing.

Once we were able to identify the problematic queries then the rest was routine query optimization – 10 minutes work using Percona Cloud Tools for what might have been an hour using traditional methods!

For those of you wondering how else this can be done, assuming you detected the CPU spike / QPS drop (perhaps you are using Graphite or other tool that can deliver per-second resolution) then you’d also need to be capturing the slow query log at a good enough resolution level (I prefer long_query_time=0 to just get it all), and then be adept at leveraging pt-query-digest with –since and –until options to narrow down your range of queries.  The significant drawback to this approach is that each time you want to tweak your time range you probably need to stream through a fairly large slow log file multiple times which can be both CPU and disk intensive operations, which means it can take some time (probably minutes, maybe hours) depending on the size of your log file.  Certainly a workable approach but nowhere near as quick as reloading a page in your browser :)

So what are you waiting for? Start using Percona Cloud Tools today, it’s free! Register for the free beta here.

The post Using Percona Cloud Tools to solve real-world MySQL problems appeared first on MySQL Performance Blog.

Jan
06
2015
--

Getting mutex information from MySQL’s performance_schema

We have been using SHOW ENGINE INNODB MUTEX command for years. It shows us mutex and rw-lock information that could be useful during service troubleshooting in case of performance problems. As Morgan Tocker announced in his blog post the command will be removed from MySQL 5.7 and we have to use performance_schema to get that info.

The documentation of MySQL also says that most of the command output has been removed from 5.6 and that we can find similar info in performance_schema. It doesn’t show any examples of how to use performance_schema or what is the query we need to use from now on. It is also important to mention that 5.6 doesn’t show any warning about the feature being deprecated.

This is a short blog post to show how to configure performance_schema and get the info we need. Hoping it will end up in the official documentation in some way.

The instruments we need are not enabled by default. Those are in wait/synch/mutex/% so the config line we need to use is:

performance-schema-instrument='wait/synch/mutex/innodb/%=ON'

Then, just compare the results from an idle Percona Server 5.6. First the output of SHOW ENGINE…

mysql> show engine innodb mutex;
+--------+------------------------------+------------+
| Type   | Name                         | Status     |
+--------+------------------------------+------------+
| InnoDB | &buf_pool->flush_state_mutex | os_waits=1 |
| InnoDB | &log_sys->checkpoint_lock    | os_waits=2 |
+--------+------------------------------+------------+

Now the results from the query that get us the mutex information from performance_schema:

mysql> SELECT EVENT_NAME, SUM_TIMER_WAIT/1000000000 WAIT_MS, COUNT_STAR FROM performance_schema.events_waits_summary_global_by_event_name
WHERE SUM_TIMER_WAIT > 0
AND EVENT_NAME LIKE 'wait/synch/mutex/innodb/%'
ORDER BY SUM_TIMER_WAIT DESC, COUNT_STAR DESC;
+----------------------------------------------------+---------+------------+
| EVENT_NAME                                         | WAIT_MS | COUNT_STAR |
+----------------------------------------------------+---------+------------+
| wait/synch/mutex/innodb/log_sys_mutex              | 11.1054 |      28279 |
| wait/synch/mutex/innodb/buf_pool_flush_state_mutex |  9.7611 |      94095 |
| wait/synch/mutex/innodb/os_mutex                   |  5.3339 |      58515 |
| wait/synch/mutex/innodb/dict_sys_mutex             |  2.4108 |       4033 |
| wait/synch/mutex/innodb/flush_list_mutex           |  2.3688 |       8036 |
| wait/synch/mutex/innodb/lock_wait_mutex            |  2.2412 |       4016 |
| wait/synch/mutex/innodb/buf_pool_LRU_list_mutex    |  2.1912 |       4182 |
| wait/synch/mutex/innodb/fil_system_mutex           |  0.9789 |       5060 |
| wait/synch/mutex/innodb/mutex_list_mutex           |  0.1723 |       8523 |
| wait/synch/mutex/innodb/rw_lock_list_mutex         |  0.1706 |       8245 |
| wait/synch/mutex/innodb/srv_innodb_monitor_mutex   |  0.0102 |         65 |
| wait/synch/mutex/innodb/recv_sys_mutex             |  0.0050 |        146 |
| wait/synch/mutex/innodb/buf_pool_free_list_mutex   |  0.0048 |        165 |
| wait/synch/mutex/innodb/trx_mutex                  |  0.0020 |        105 |
| wait/synch/mutex/innodb/srv_sys_mutex              |  0.0012 |         11 |
| wait/synch/mutex/innodb/trx_sys_mutex              |  0.0010 |         29 |
| wait/synch/mutex/innodb/lock_mutex                 |  0.0008 |         26 |
| wait/synch/mutex/innodb/innobase_share_mutex       |  0.0004 |          5 |
| wait/synch/mutex/innodb/buf_dblwr_mutex            |  0.0003 |          4 |
| wait/synch/mutex/innodb/file_format_max_mutex      |  0.0003 |          6 |
| wait/synch/mutex/innodb/rseg_mutex                 |  0.0002 |          7 |
| wait/synch/mutex/innodb/recv_writer_mutex          |  0.0001 |          1 |
| wait/synch/mutex/innodb/ut_list_mutex              |  0.0001 |          1 |
| wait/synch/mutex/innodb/ibuf_mutex                 |  0.0001 |          2 |
| wait/synch/mutex/innodb/log_flush_order_mutex      |  0.0000 |          1 |
+----------------------------------------------------+---------+------------+

The difference is clear. We get much more information from Performance Schema. In my personal opinion, despite the extra resources needed by Performance Schema, the change is for the better.

The post Getting mutex information from MySQL’s performance_schema appeared first on MySQL Performance Blog.

Dec
29
2014
--

How well does your table fit in the InnoDB buffer pool in MySQL 5.6+?

Some time ago, Peter Zaitsev posted a blog titled “How well does your table fits in innodb buffer pool?” He used some special INFORMATION_SCHEMA tables developed for Percona Server 5.1 to report how much of each InnoDB table and index resides in your buffer pool.

As Peter pointed out, you can use this view into the buffer pool to watch a buffer pool warm up with pages as you run queries. You can also use it for capacity planning. If you expect some tables need to be fully loaded in the buffer pool to be used efficiently, but the buffer pool isn’t large enough to hold them, then it’s time to increase the size of the buffer pool.

The problem, however, was that system tables change from version to version. Specifically, the INNODB_BUFFER_POOL_PAGES_INDEX table no longer exists in Percona Server 5.6, and the INNODB_INDEX_STATS table changed some column names in Percona Server 5.5.8, and the table no longer exists in Percona Server 5.6. So many of the comments on Peter’s blog rightly pointed out that the example query didn’t work on subsequent versions of Percona Server. And MySQL Community Edition at the time didn’t have the feature at all. They asked for an update to the blog post.

So here’s an updated, simplified query to report the content of your buffer pool, tested on the most recent versions.

Percona Server 5.1 and 5.5:

USE information_schema;
SET @page_size = @@innodb_page_size;
SET @bp_pages = @@innodb_buffer_pool_size/@page_size;
SELECT P.TABLE_NAME, P.PAGE_TYPE,
CASE WHEN P.INDEX_NAME IS NULL THEN NULL WHEN P.TABLE_NAME LIKE '`SYS_%' THEN P.INDEX_NAME WHEN P.INDEX_NAME <> 'PRIMARY' THEN 'SECONDARY' ELSE 'PRIMARY' END AS INDEX_TYPE,
COUNT(DISTINCT P.PAGE_NUMBER) AS PAGES,
ROUND(100*COUNT(DISTINCT P.PAGE_NUMBER)/@bp_pages,2) AS PCT_OF_BUFFER_POOL,
CASE WHEN P.TABLE_NAME IS NULL THEN NULL WHEN P.TABLE_NAME LIKE 'SYS_%' THEN NULL ELSE ROUND(100*COUNT(DISTINCT P.PAGE_NUMBER)/CASE P.INDEX_NAME WHEN 'PRIMARY' THEN TS.DATA_LENGTH/@page_size ELSE TS.INDEX_LENGTH/@page_size END, 2) END AS PCT_OF_INDEX
FROM INNODB_BUFFER_PAGE AS P
JOIN INNODB_SYS_TABLES AS T ON P.SPACE = T.SPACE
JOIN TABLES AS TS ON (T.SCHEMA, T.NAME) = (TS.TABLE_SCHEMA, TS.TABLE_NAME)
WHERE TS.TABLE_SCHEMA <> 'mysql'
GROUP BY TABLE_NAME, PAGE_TYPE, INDEX_TYPE;

MySQL 5.6 and 5.7 (this also works on Percona Server 5.6):

USE information_schema;
SET @page_size = @@innodb_page_size;
SET @bp_pages = @@innodb_buffer_pool_size/@page_size;
SELECT P.TABLE_NAME, P.PAGE_TYPE,
CASE WHEN P.INDEX_NAME IS NULL THEN NULL WHEN P.TABLE_NAME LIKE '`SYS_%' THEN P.INDEX_NAME WHEN P.INDEX_NAME <> 'PRIMARY' THEN 'SECONDARY' ELSE 'PRIMARY' END AS INDEX_TYPE,
COUNT(DISTINCT P.PAGE_NUMBER) AS PAGES,
ROUND(100*COUNT(DISTINCT P.PAGE_NUMBER)/@bp_pages,2) AS PCT_OF_BUFFER_POOL,
CASE WHEN P.TABLE_NAME IS NULL THEN NULL WHEN P.TABLE_NAME LIKE 'SYS_%' THEN NULL ELSE ROUND(100*COUNT(DISTINCT P.PAGE_NUMBER)/CASE P.INDEX_NAME WHEN 'PRIMARY' THEN TS.DATA_LENGTH/@page_size ELSE TS.INDEX_LENGTH/@page_size END, 2) END AS PCT_OF_INDEX
FROM INNODB_BUFFER_PAGE AS P
JOIN INNODB_SYS_TABLES AS T ON P.SPACE = T.SPACE
JOIN TABLES AS TS ON T.NAME = CONCAT(TS.TABLE_SCHEMA, '/', TS.TABLE_NAME)
WHERE TS.TABLE_SCHEMA <> 'mysql'
GROUP BY TABLE_NAME, PAGE_TYPE, INDEX_TYPE;

In both cases, the output looks something like the following (if I have read from a single table called test.foo):

+--------------+-------------------+------------+-------+--------------------+--------------+
| TABLE_NAME   | PAGE_TYPE         | INDEX_TYPE | PAGES | PCT_OF_BUFFER_POOL | PCT_OF_INDEX |
+--------------+-------------------+------------+-------+--------------------+--------------+
| NULL         | FILE_SPACE_HEADER | NULL       |     1 |               0.00 |         NULL |
| NULL         | IBUF_BITMAP       | NULL       |     1 |               0.00 |         NULL |
| NULL         | INODE             | NULL       |     1 |               0.00 |         NULL |
| `test`.`foo` | INDEX             | PRIMARY    |  2176 |               3.32 |        98.37 |
| `test`.`foo` | INDEX             | SECONDARY  |  2893 |               4.41 |        88.47 |
+--------------+-------------------+------------+-------+--------------------+--------------+

Unfortunately, the INFORMATION_SCHEMA tables report total size of secondary indexes for a table, but not the size of each index individually. Therefore this query shows the percent of index only for the primary index (which is also the clustered index, i.e. the table itself), and then all other secondary indexes grouped together.

PERFORMANCE_SCHEMA solution

The PERFORMANCE_SCHEMA also includes some information about the contents of the buffer pool. The MySQL SYS Schema makes it easy to query this. But this view doesn’t calculate the percentage of each table in the buffer pool, nor the percentage of the buffer pool occupied by each table.

mysql> SELECT * FROM sys.innodb_buffer_stats_by_table;
+---------------+----------------------+------------+------------+-------+--------------+-----------+-------------+
| object_schema | object_name          | allocated  | data       | pages | pages_hashed | pages_old | rows_cached |
+---------------+----------------------+------------+------------+-------+--------------+-----------+-------------+
| test          | foo                  | 149.64 MiB | 106.19 MiB |  9577 |         9577 |      9577 |     1050490 |
| InnoDB System | SYS_TABLES           | 160.00 KiB | 91.24 KiB  |    10 |           10 |        10 |         594 |
| InnoDB System | SYS_INDEXES          | 128.00 KiB | 93.59 KiB  |     8 |            8 |         8 |        1345 |
| InnoDB System | SYS_COLUMNS          | 80.00 KiB  | 47.13 KiB  |     5 |            5 |         5 |         761 |
| InnoDB System | SYS_DATAFILES        | 48.00 KiB  | 16.40 KiB  |     3 |            3 |         3 |         246 |
| InnoDB System | SYS_FIELDS           | 48.00 KiB  | 16.02 KiB  |     3 |            3 |         3 |         377 |
| InnoDB System | SYS_FOREIGN          | 48.00 KiB  | 0 bytes    |     3 |            3 |         3 |           0 |
| InnoDB System | SYS_TABLESPACES      | 48.00 KiB  | 15.83 KiB  |     3 |            3 |         3 |         242 |
| InnoDB System | SYS_FOREIGN_COLS     | 16.00 KiB  | 0 bytes    |     1 |            1 |         1 |           0 |
. . .

The post How well does your table fit in the InnoDB buffer pool in MySQL 5.6+? appeared first on MySQL Performance Blog.

Feb
11
2014
--

PERFORMANCE_SCHEMA vs Slow Query Log

A couple of weeks ago, shortly after Vadim wrote about Percona Cloud Tools and using Slow Query Log to capture the data, Mark Leith asked why don’t we just use Performance Schema instead? This is an interesting question and I think it deserves its own blog post to talk about.

First, I would say main reason for using Slow Query Log is compatibility. Basic Slow query log with microsecond query time precision is available starting in MySQL 5.1, while events_statements_summary_by_digest table was only added in MySQL 5.6 which was out for about a year now but which is still far from complete market domination. It is especially interesting if you look at the low-end market – users who just run some web applications using whatever MySQL Version their hosting provider installed for them. If you look at WordPress Users for example you will see MySQL 5.6 at just 1.3% as of today. As time passes and MySQL 5.6 takes a larger share of the market we surely should add support for Performance Schema based query sampling to Percona Cloud Tools.

The second reason is amount of data available. There is a fair amount of data which Performance Schema digest table providers including some which are not available in Percona Server logs:

mysql> select * from events_statements_summary_by_digest where digest_text like "%sbtest%" \G
*************************** 1. row ***************************
                SCHEMA_NAME: sbtest
                     DIGEST: 2062ac01bc1798df1eebd3e111a22b59
                DIGEST_TEXT: SELECT c FROM sbtest WHERE id = ?
                 COUNT_STAR: 882262
             SUM_TIMER_WAIT: 933683089690000
             MIN_TIMER_WAIT: 106418000
             AVG_TIMER_WAIT: 1058283000
             MAX_TIMER_WAIT: 1031299058000
              SUM_LOCK_TIME: 60853469000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 889205
          SUM_ROWS_EXAMINED: 890279
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2014-02-10 17:39:39
                  LAST_SEEN: 2014-02-10 17:40:39
1 row in set (0.00 sec)

BTW – note Rows Sent here not being equal to rows examined while in reality they should be exactly the same for this benchmark. This is the approximate accounting of Performance Schema in action, though.

Now compare it to the sample for the same query in the slow query log in Percona Server

SET timestamp=1392071614;
SELECT c from sbtest where id=387872;
# Time: 140210 17:33:34.837517
# User@Host: root[root] @ localhost []  Id:    95
# Schema: sbtest  Last_errno: 0  Killed: 0
# Query_time: 0.001000  Lock_time: 0.000054  Rows_sent: 1  Rows_examined: 1  Rows_affected: 0
# Bytes_sent: 74  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# InnoDB_trx_id: 90E34CF
# QC_Hit: No  Full_scan: No  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
# Filesort: No  Filesort_on_disk: No  Merge_passes: 0
#   InnoDB_IO_r_ops: 0  InnoDB_IO_r_bytes: 0  InnoDB_IO_r_wait: 0.000000
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 1
# Log_slow_rate_type: query  Log_slow_rate_limit: 100

What I believe is the most valuable here is the information about Innodb IO which instantly allows us to isolate the query patterns which are disk IO bound as well as information about Bytes Sent which allows to see which queries are responsible for generating high volumes of network traffic.

I wish Performance Schema would be enhanced to return data in something like JSON where for each digest the top waits are accounted as in reality it can be different by the query. Some queries might be waiting on IO other on Locks, yet another could be bound by some specific mutexes. Having exact information about what limits performance of queries of the specific type would be a gem.

The third reason for using Slow Query Log is using placeholders. Note in the query above has “SELECT c FROM sbtest WHERE id = ?” which is not very convenient – I can’t even run EXPLAIN for such query to see what could be the reason for its slowness. Log contains exact queries and we are able to show exact queries in reports (pt-query-digest and Percona Cloud Tools) or you can opt for seeing only query digests if you do not want to see the values for privacy/security reasons. Picking the constant for a query with worse plan usually works very well to check out worse case scenario.

This might look like very simple problem – why you can’t just come up with ID and reconstruct the query but for more complicated queries with multiple conditions it is virtually impossible to reconstruct the realistic query.

Now in theory you can look up actual query from events_statements_history_long and join the data together, however it does not really work at the high query rates as it is very likely rare queries will not have a sample available in the history table.

The forth reason is support for prepared statements. Enable prepared statements and you will not see the actual query in the digest. This may or may not be an issue for your application but it further limits usability of this feature. I can’t count on simply looking at events_statements_summary_by_digest to always find which queries are responsible for majority of the load.

The fifth reason is performance or actually not much of a reason. I really think Performance Schema overhead is reasonable for most workloads. In simple queries benchmark which I’ve done:

sysbench --test=oltp --oltp-test-mode=simple  --num-threads=16 --max-requests=0 --max-time=60   --mysql-user=root --oltp-table-size=1000000 run

On my old server I got some 20.2K QPS with Performance Schema Disabled and 19.4 QPS with Performance Schema enabled which is overhead of less than 5%.

For most workloads paying 5% to have insight about what is happening with the system is a very fair trade.

The slow query log overhead actually can be much larger. The moderate level of details “microtime” resulted in 15.1K queries and log_slow_verbosity=”full” takes this value down to 11.6K having over 40% overhead. Note I designed this test as worse case scenario and for more complicated queries the overhead is likely to be less (while overhead with Performance Schema can stay the same or even increase depending on what queries are doing).

Some people set long_query_time to some non zero value to reduce amount of queries logged. This is bad idea because the workload logged will be very different from your real one – chances are majority of your load comes from simple quick queries which will be very unrepresented with non zero long query time with only outliers logged.

A much better idea is to enable Sampling which is available in latest version of Percona Server – this way only one out of every so many queries will be logged:

mysql> set global log_slow_rate_limit=100;
Query OK, 0 rows affected (0.00 sec)
mysql> set global log_slow_rate_type="query";
Query OK, 0 rows affected (0.00 sec)

This will get one out ever 100 queries randomly logged which should give you good idea of your workload without such skew. It works well unless you have some rare and very complicated queries which impact your workload disproportionally and which you can’t ignore for performance analyses. To deal with this situation we added slow_query_log_always_write_time option to Percona Server, which allows you to always log such queries in the log even if they would not be selected because of sampling.

Enabling sampling 1/100 queries for this workload with full level of details I get 19.8K queries giving us overhead less than 2% which is even less than Performance Schema and selecting 1/1000 queries to be logged I can get overhead to about 1%. So with Slow Query Log I can make a choice between accuracy and overhead.

I wish Performance Schema would offer something similar – instead of figuring out what probes and statistic tables I need (not all of them are enabled by default) I could just chose to get the sampled data and play with accuracy vs overhead instead of missing the data all together.

Summary: There is a great amount of data in Performance Schema in MySQL 5.6 and Percona Server 5.6 though there are a number of reasons that you also might not want to discard the old and proven tools based on the slow query log just yet.

P.S., If you’re interested in seeing Query Performance Analyses in action please join Vadim’s webinar on Wednesday Feb 12. If you missed it check out recording at that same link.

The post PERFORMANCE_SCHEMA vs Slow Query Log appeared first on MySQL Performance Blog.

Powered by WordPress | Theme: Aeros 2.0 by TheBuckmaker.com