MySQL « Chris on MySQL

Posts Tagged ‘MySQL’

Using EXPLAIN EXTENDED / SHOW WARNINGS to Help Troubleshoot Inefficient Queries in MySQL

Thursday, July 8th, 2010

When examining the execution plan of troublesome queries in MySQL, most users are aware of using EXPLAIN. However, an often overlooked, yet very helpful extension of EXPLAIN, is EXPLAIN EXTENDED coupled with the SHOW WARNINGS command.

The reason being is because it provides a little more information about how the optimizer processes the query, and thus it could help to quickly identify a problem that you might not otherwise recognize with just EXPLAIN.

For instance, here is a common query which could be inefficient:

SELECT id FROM t WHERE id='1';

And here is the CREATE TABLE output:

mysql> show create table t\G
*************************** 1. row ***************************
       Table: t
Create Table: CREATE TABLE `t` (
  `id` decimal(10,0) default NULL,
  KEY `id` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

You can see it’s a very basic table, and a very basic query.

And looking at the EXPLAIN output, everything still appears normal:

mysql> explain select id from t where id='1';
+----+-------------+-------+------+---------------+------+---------+-------+------+--------------------------+
| id | select_type | table | type | possible_keys | key  | key_len | ref   | rows | Extra                    |
+----+-------------+-------+------+---------------+------+---------+-------+------+--------------------------+
|  1 | SIMPLE      | t     | ref  | id            | id   | 6       | const |    1 | Using where; Using index |
+----+-------------+-------+------+---------------+------+---------+-------+------+--------------------------+
1 row in set (0.00 sec)

However, now let’s look at the EXPLAIN EXTENDED and SHOW WARNINGS output:

mysql> explain extended select id from t where id='1';
+----+-------------+-------+------+---------------+------+---------+-------+------+--------------------------+
| id | select_type | table | type | possible_keys | key  | key_len | ref   | rows | Extra                    |
+----+-------------+-------+------+---------------+------+---------+-------+------+--------------------------+
|  1 | SIMPLE      | t     | ref  | id            | id   | 6       | const |    1 | Using where; Using index |
+----+-------------+-------+------+---------------+------+---------+-------+------+--------------------------+
1 row in set, 1 warning (0.00 sec)

mysql> show warnings;
+-------+------+----------------------------------------------------------------------------------------------+
| Level | Code | Message                                                                                      |
+-------+------+----------------------------------------------------------------------------------------------+
| Note  | 1003 | select `testing`.`t`.`id` AS `id` from `testing`.`t` where (`testing`.`t`.`id` = _latin1'1') |
+-------+------+----------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

In the WHERE clause of the SHOW WARNINGS output, you see this:

where (`testing`.`t`.`id` = _latin1'1')

The _latin1′1′ is key, as it shows the value of 1 is getting cast as a latin1 value. This is because we surrounded the 1 with single quotes in the query.

Note that this does not happen if you do not surround the 1 with single quotes:

mysql> show warnings;
+-------+------+-------------------------------------------------------------------------------------+
| Level | Code | Message                                                                             |
+-------+------+-------------------------------------------------------------------------------------+
| Note  | 1003 | select `testing`.`t`.`id` AS `id` from `testing`.`t` where (`testing`.`t`.`id` = 1) |
+-------+------+-------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

In this example, the constant value of 1 is being cast, which is not horrible, but still not as efficient as it should be. However, depending on how the query is written, I’ve seen where it might choose to cast/convert the row retrived from the database (especially in a JOIN scenario - it will need to convert one column if they differ). These conversions or casts can be very inefficient (especially if within a JOIN or worse, a sub-query), and would not be otherwise caught without using EXPLAIN EXTENDED / SHOW WARNINGS.

And in addition to the above example, it is common to see similar types of conversions occurring if you try to match two columns whose character sets differ. This can be another easy-to-overlook problem, which can lead to poor performance, and you wouldn’t know it wasn’t running efficiently unless you used EXPLAIN EXTENDED (or unless it brings your system to a halt during a heavy load ..).

So in conclusion, consider using EXPLAIN EXTENDED / SHOW WARNINGS in lieu of just EXPLAIN when analyzing your queries.

Note: If you are using pre-5.1.46, you may want to consider running both EXPLAIN and EXPLAIN EXTENDED to ensure the optimization plans match. This is due to the following bug which existed:

http://bugs.mysql.com/bug.php?id=47669

Click here to give this article a “Thumbs Up” on Planet MySQL !

Tags: charset mismatch, EXPLAIN, EXPLAIN EXTENDED, MySQL, query optimization, SHOW WARNINGS
Posted in MySQL | 1 Comment »

Ease of Switching to the InnoDB Plugin and the Numerous Benefits

Thursday, July 1st, 2010

In my last post, I discussed how to troubleshoot InnoDB locks using the new InnoDB Plugin’s new Information Schema tables.

However, that got me to thinking about how many MySQL 5.1 users who have still not switched to use the plugin as opposed to the built-in version of InnoDB.

There are many advantages to using the plugin as opposed to the built-in version (aside from just the new I_S tables, and more importantly, numerous performance enhancements), and it’s breeze to set up, so I wanted to provide a quick start guide to using the new InnoDB plugin.

Note that the InnoDB plugin is now GA (as of plugin version 1.0.7) and as of 5.1.38 it is included with the MySQL downloads (it just needs to be enabled).

If you’re running pre-5.1.38, then you may want to consider upgrading to a newer MySQL anyways (5.1.48 is the latest as of this posting). But if not, then you’ll need to download the plugin and extract it.

But if you’re using 5.1.38 or newer, then just take the following steps:

1. Update your my.cnf (or my.ini) by adding the following 2 lines (note the dll should already exist in BASEDIR\lib\plugin):

ignore_builtin_innodb
plugin-load=innodb=ha_innodb_plugin.dll;innodb_trx=ha_innodb_plugin.dll;
                innodb_locks=ha_innodb_plugin.dll;innodb_lock_waits=ha_innodb_plugin.dll;
                innodb_cmp=ha_innodb_plugin.dll;innodb_cmp_reset=ha_innodb_plugin.dll;
                innodb_cmpmem=ha_innodb_plugin.dll;innodb_cmpmem_reset=ha_innodb_plugin.dll

2. Restart mysqld

3. Now you can check some various commands to verify it’s enabled.

I’ll post the BEFORE and AFTER, so you can see the differences:

SHOW GLOBAL VARIABLES LIKE ‘%innodb%’ Output:

BEFORE Plugin:

mysql> show global variables like '%innodb%';
+-----------------------------------------+------------------------+
| Variable_name                           | Value                  |
+-----------------------------------------+------------------------+
| have_innodb                             | YES                    |
| ignore_builtin_innodb                   | OFF                    |
| innodb_adaptive_hash_index              | ON                     |
| innodb_additional_mem_pool_size         | 2097152                |
| innodb_autoextend_increment             | 8                      |
| innodb_autoinc_lock_mode                | 1                      |
| innodb_buffer_pool_size                 | 49283072               |
| innodb_checksums                        | ON                     |
| innodb_commit_concurrency               | 0                      |
| innodb_concurrency_tickets              | 500                    |
| innodb_data_file_path                   | ibdata1:10M:autoextend |
| innodb_data_home_dir                    |                        |
| innodb_doublewrite                      | ON                     |
| innodb_fast_shutdown                    | 1                      |
| innodb_file_io_threads                  | 4                      |
| innodb_file_per_table                   | ON                     |
| innodb_flush_log_at_trx_commit          | 1                      |
| innodb_flush_method                     |                        |
| innodb_force_recovery                   | 0                      |
| innodb_lock_wait_timeout                | 50                     |
| innodb_locks_unsafe_for_binlog          | OFF                    |
| innodb_log_buffer_size                  | 1048576                |
| innodb_log_file_size                    | 25165824               |
| innodb_log_files_in_group               | 2                      |
| innodb_log_group_home_dir               | .\                     |
| innodb_max_dirty_pages_pct              | 90                     |
| innodb_max_purge_lag                    | 0                      |
| innodb_mirrored_log_groups              | 1                      |
| innodb_open_files                       | 300                    |
| innodb_rollback_on_timeout              | OFF                    |
| innodb_stats_on_metadata                | ON                     |
| innodb_support_xa                       | ON                     |
| innodb_sync_spin_loops                  | 20                     |
| innodb_table_locks                      | ON                     |
| innodb_thread_concurrency               | 8                      |
| innodb_thread_sleep_delay               | 10000                  |
| innodb_use_legacy_cardinality_algorithm | ON                     |
+-----------------------------------------+------------------------+
37 rows in set (0.00 sec)

AFTER Plugin:

mysql> show global variables like '%innodb%';
+---------------------------------+------------------------+
| Variable_name                   | Value                  |
+---------------------------------+------------------------+
| have_innodb                     | YES                    |
| ignore_builtin_innodb           | ON                     |
| innodb_adaptive_flushing        | ON                     |
| innodb_adaptive_hash_index      | ON                     |
| innodb_additional_mem_pool_size | 2097152                |
| innodb_autoextend_increment     | 8                      |
| innodb_autoinc_lock_mode        | 1                      |
| innodb_buffer_pool_size         | 49283072               |
| innodb_change_buffering         | inserts                |
| innodb_checksums                | ON                     |
| innodb_commit_concurrency       | 0                      |
| innodb_concurrency_tickets      | 500                    |
| innodb_data_file_path           | ibdata1:10M:autoextend |
| innodb_data_home_dir            |                        |
| innodb_doublewrite              | ON                     |
| innodb_fast_shutdown            | 1                      |
| innodb_file_format              | Antelope               |
| innodb_file_format_check        | Antelope               |
| innodb_file_per_table           | ON                     |
| innodb_flush_log_at_trx_commit  | 1                      |
| innodb_flush_method             |                        |
| innodb_force_recovery           | 0                      |
| innodb_io_capacity              | 200                    |
| innodb_lock_wait_timeout        | 50                     |
| innodb_locks_unsafe_for_binlog  | OFF                    |
| innodb_log_buffer_size          | 1048576                |
| innodb_log_file_size            | 25165824               |
| innodb_log_files_in_group       | 2                      |
| innodb_log_group_home_dir       | .\                     |
| innodb_max_dirty_pages_pct      | 75                     |
| innodb_max_purge_lag            | 0                      |
| innodb_mirrored_log_groups      | 1                      |
| innodb_old_blocks_pct           | 37                     |
| innodb_old_blocks_time          | 0                      |
| innodb_open_files               | 300                    |
| innodb_read_ahead_threshold     | 56                     |
| innodb_read_io_threads          | 4                      |
| innodb_replication_delay        | 0                      |
| innodb_rollback_on_timeout      | OFF                    |
| innodb_spin_wait_delay          | 6                      |
| innodb_stats_on_metadata        | ON                     |
| innodb_stats_sample_pages       | 8                      |
| innodb_strict_mode              | OFF                    |
| innodb_support_xa               | ON                     |
| innodb_sync_spin_loops          | 30                     |
| innodb_table_locks              | ON                     |
| innodb_thread_concurrency       | 8                      |
| innodb_thread_sleep_delay       | 10000                  |
| innodb_use_sys_malloc           | ON                     |
| innodb_version                  | 1.0.9                  |
| innodb_write_io_threads         | 4                      |
+---------------------------------+------------------------+
51 rows in set (0.00 sec)

In the above, with the plugin, you can see the value of ignore_builtin_innodb is now “ON”.

Also, the innodb_file_format and innodb_file_format_check is “Antelope” for this particular version of the plugin.

There are also a number of new variables, such as innodb_adaptive_flushing, innodb_change_buffering, innodb_file_format, innodb_file_format_check, innodb_io_capacity, innodb_old_blocks_pct, innodb_old_blocks_time, innodb_read_ahead_threshold, innodb_read_io_threads, innodb_replication_delay, innodb_spin_wait_delay, innodb_stats_sample_pages, innodb_stats_sample_pages, innodb_strict_mode, innodb_use_sys_malloc, innodb_version, and innodb_write_io_threads.

The only two missing from the new plugin are innodb_file_io_threads and innodb_use_legacy_cardinality_algorithm.

SELECT * FROM PLUGINS Output:

BEFORE Plugin:

mysql> use information_schema;
Database changed
mysql> select * from plugins;
+-------------+----------------+---------------+----------------+---------------------+----------------+------------------------+--------------------------------------------+--------------------------------------------------------------------------+----------------+
| PLUGIN_NAME | PLUGIN_VERSION | PLUGIN_STATUS | PLUGIN_TYPE    | PLUGIN_TYPE_VERSION | PLUGIN_LIBRARY | PLUGIN_LIBRARY_VERSION | PLUGIN_AUTHOR                              | PLUGIN_DESCRIPTION                                                       | PLUGIN_LICENSE |
+-------------+----------------+---------------+----------------+---------------------+----------------+------------------------+--------------------------------------------+--------------------------------------------------------------------------+----------------+
| binlog      | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | MySQL AB                                   | This is a pseudo storage engine to represent the binlog in a transaction | GPL            |
| ARCHIVE     | 3.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | Brian Aker, MySQL AB                       | Archive storage engine                                                   | GPL            |
| BLACKHOLE   | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | MySQL AB                                   | /dev/null storage engine (anything you write to it disappears)           | GPL            |
| CSV         | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | Brian Aker, MySQL AB                       | CSV storage engine                                                       | GPL            |
| FEDERATED   | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | Patrick Galbraith and Brian Aker, MySQL AB | Federated MySQL storage engine                                           | GPL            |
| MEMORY      | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | MySQL AB                                   | Hash based, stored in memory, useful for temporary tables                | GPL            |
| InnoDB      | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | Innobase OY                                | Supports transactions, row-level locking, and foreign keys               | GPL            |
| MyISAM      | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | MySQL AB                                   | Default engine as of MySQL 3.23 with great performance                   | GPL            |
| MRG_MYISAM  | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | MySQL AB                                   | Collection of identical MyISAM tables                                    | GPL            |
| partition   | 1.0            | ACTIVE        | STORAGE ENGINE | 50148.0             | NULL           | NULL                   | Mikael Ronstrom, MySQL AB                  | Partition Storage Engine Helper                                          | GPL            |
+-------------+----------------+---------------+----------------+---------------------+----------------+------------------------+--------------------------------------------+--------------------------------------------------------------------------+----------------+
10 rows in set (0.01 sec)

AFTER Plugin:

mysql> use information_schema; Database changed mysql> select * from plugins; +---------------------+---- | PLUGIN_NAME +---------------------+---- | binlog              | 1.0 | ARCHIVE             | 3.0 | BLACKHOLE           | 1.0 | CSV                 | 1.0 | FEDERATED           | 1.0 | MEMORY              | 1.0 | MyISAM              | 1.0 | MRG_MYISAM          | 1.0 | partition           | 1.0 | InnoDB              | 1.0 | INNODB_TRX          | 1.0 | INNODB_LOCKS        | 1.0 | INNODB_LOCK_WAITS   | 1.0 | INNODB_CMP          | 1.0 | INNODB_CMP_RESET    | 1.0 | INNODB_CMPMEM       | 1.0 | INNODB_CMPMEM_RESET | 1.0 +---------------------+---- 17 rows in set (0.01 sec)

------------+---------------+--------------------+---------------------+----------------------+------------------------+--------------------------------------------+--------------------------------------------------------------------------+----------------+ | PLUGIN_VERSION | PLUGIN_STATUS | PLUGIN_TYPE | PLUGIN_TYPE_VERSION | PLUGIN_LIBRARY | PLUGIN_LIBRARY_VERSION | PLUGIN_AUTHOR | PLUGIN_DESCRIPTION | PLUGIN_LICENSE | ------------+---------------+--------------------+---------------------+----------------------+------------------------+--------------------------------------------+--------------------------------------------------------------------------+----------------+ | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | MySQL AB | This is a pseudo storage engine to represent the binlog in a transaction | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | Brian Aker, MySQL AB | Archive storage engine | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | MySQL AB | /dev/null storage engine (anything you write to it disappears) | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | Brian Aker, MySQL AB | CSV storage engine | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | Patrick Galbraith and Brian Aker, MySQL AB | Federated MySQL storage engine | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | MySQL AB | Hash based, stored in memory, useful for temporary tables | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | MySQL AB | Default engine as of MySQL 3.23 with great performance | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | MySQL AB | Collection of identical MyISAM tables | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | NULL | NULL | Mikael Ronstrom, MySQL AB | Partition Storage Engine Helper | GPL | | ACTIVE | STORAGE ENGINE | 50148.0 | ha_innodb_plugin.dll | 1.0 | Innobase Oy | Supports transactions, row-level locking, and foreign keys | GPL | | ACTIVE | INFORMATION SCHEMA | 50148.0 | ha_innodb_plugin.dll | 1.0 | Innobase Oy | InnoDB transactions | GPL | | ACTIVE | INFORMATION SCHEMA | 50148.0 | ha_innodb_plugin.dll | 1.0 | Innobase Oy | InnoDB conflicting locks | GPL | | ACTIVE | INFORMATION SCHEMA | 50148.0 | ha_innodb_plugin.dll | 1.0 | Innobase Oy | InnoDB which lock is blocking which | GPL | | ACTIVE | INFORMATION SCHEMA | 50148.0 | ha_innodb_plugin.dll | 1.0 | Innobase Oy | Statistics for the InnoDB compression | GPL | | ACTIVE | INFORMATION SCHEMA | 50148.0 | ha_innodb_plugin.dll | 1.0 | Innobase Oy | Statistics for the InnoDB compression; reset cumulated counts | GPL | | ACTIVE | INFORMATION SCHEMA | 50148.0 | ha_innodb_plugin.dll | 1.0 | Innobase Oy | Statistics for the InnoDB compressed buffer pool | GPL | | ACTIVE | INFORMATION SCHEMA | 50148.0 | ha_innodb_plugin.dll | 1.0 | Innobase Oy | Statistics for the InnoDB compressed buffer pool; reset cumulated counts | GPL | ------------+---------------+--------------------+---------------------+----------------------+------------------------+--------------------------------------------+--------------------------------------------------------------------------+----------------+

In the above output, you can see the values for the InnoDB Plugin have changed. For instance, the PLUGIN_LIBRARY now shows ha_innodb_plugin.dll. Additionally, you can see the new INFORMATION SCHEMA plugins listed, which are INNODB_TRX, INNODB_LOCKS, INNODB_LOCK_WAITS, INNODB_CMP, INNODB_CMP_RESET, INNODB_CMPMEM, INNODB_CMPMEM_RESET.

Lastly, I’ll just post the output from SHOW ENGINE INNODB STATUS from the new Plugin only. There’s new information provided here as well (see “Pages made young 0, not young 0″ amongst numerous others).

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
100622 19:22:06 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 39 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 1_second, 1 sleeps, 0 10_second, 2 background, 2 flush
srv_master_thread log flush and writes: 1
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3, signal count 3
Mutex spin waits 0, rounds 0, OS waits 0
RW-shared spins 3, OS waits 3; RW-excl spins 0, OS waits 0
Spin rounds per wait: 0.00 mutex, 30.00 RW-shared, 0.00 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 20E00
Purge done for trx's n:o < 20C18 undo n:o < 0
History list length 11
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started, OS thread id 8812
MySQL thread id 1, query id 7 localhost 127.0.0.1 root
show engine innodb status
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (read thread)
I/O thread 4 state: wait Windows aio (read thread)
I/O thread 5 state: wait Windows aio (read thread)
I/O thread 6 state: wait Windows aio (write thread)
I/O thread 7 state: wait Windows aio (write thread)
I/O thread 8 state: wait Windows aio (write thread)
I/O thread 9 state: wait Windows aio (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
27 OS file reads, 7 OS file writes, 7 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 2174, seg size 2176,
0 inserts, 0 merged recs, 0 merges
Hash table size 195193, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 745473833
Log flushed up to   745473833
Last checkpoint at  745473833
0 pending log writes, 0 pending chkp writes
10 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 50184192; in additional pool allocated 0
Dictionary memory allocated 20888
Buffer pool size   3008
Free buffers       2992
Database pages     16
Old database pages 0
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 16, created 0, written 1
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s
LRU len: 16, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread id 9800, state: waiting for server activity
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.00 sec)

So in conclusion, it’s very easy to enable the InnoDB Plugin (add 2 lines to your my.cnf file and restart). So if you’re running 5.1, you should definitely consider enablig the InnoDB plugin if you haven’t already, and you will gain the following numerous benefits (posted from the manual):

Fast index creation: add or drop indexes without copying the data
Data compression: shrink tables, to significantly reduce storage and i/o
New row format: fully off-page storage of long BLOB, TEXT, and VARCHAR columns
File format management: protects upward and downward compatibility
INFORMATION_SCHEMA tables: information about compression and locking
Performance and scalability enhancements:

Faster locking for improved scalability
Using operating system memory allocators
Controlling InnoDB insert buffering
Controlling adaptive hash indexing
Changes regarding thread concurrency
Changes in read ahead algorithm
Multiple background I/O threads
Group Commit
Controlling master thread I/O rate
Controlling flushing rate of dirty pages
Using a portable PAUSE to InnoDB spin loop
Control Over Spin Lock Polling
Changing defaults of parameters
Making Buffer Cache Scan Resistant
Improvements to Crash Recovery Performance

Other changes for flexibility, ease of use and reliability:

Dynamic control of system configuration parameters
TRUNCATE TABLE reclaims space
InnoDB “strict mode”
Control over statistics estimation
Better error handling when dropping indexes
More compact output of SHOW ENGINE INNODB MUTEX
More Read Ahead Statistics

http://dev.mysql.com/doc/innodb-plugin/1.0/en/innodb-plugin-introduction-features.html

Click here to give this article a “Thumbs Up” on Planet MySQL !

Tags: innodb, innodb plugin, innodb_adaptive_flushing, innodb_change_buffering, innodb_file_format, innodb_file_format_check, innodb_io_capacity, innodb_old_blocks_pct, innodb_old_blocks_time, innodb_read_ahead_threshold, innodb_read_io_threads, innodb_replication_delay, innodb_spin_wait_delay, innodb_stats_sample_pages, innodb_strict_mode, innodb_use_sys_malloc, innodb_version, innodb_write_io_threads, MySQL, Plugin
Posted in MySQL | 3 Comments »

Debugging InnoDB Locks using the new InnoDB Plugin’s Information Schema Tables

Tuesday, June 29th, 2010

Tracking down InnoDB lock information using the new Information Schema tables provided with the InnoDB plugin has never been easier.

Long story short, the other day I was trying to identify what transaction was holding the lock for a particular UPDATE. The UPDATE would not complete and kept timing out with “Lock wait timeout exceeded; try restarting transaction”.

Of course I checked the output of SHOW ENGINE INNODB STATUS. From that output, I could tell it was the replication thread holding the lock, *since* it was the only other transaction running. But I could not verify this with output, it just had to be the case.

Next I enabled the InnoDB lock monitor, and examined that output too. Here, it showed more detail on the locks being held, however, it only shows the first 10 locks held by the replication thread. In this case, the replication thread was holding more than 2000 record locks from a large, open transaction. Needless to say, the lock I was looking for was not amongst the 10 displayed.

So I enabled InnoDB plugin (just added the following 2 lines to my config file and restarted mysqld):

ignore_builtin_innodb
plugin-load=innodb=ha_innodb_plugin.dll;innodb_trx=ha_innodb_plugin.dll;
innodb_locks=ha_innodb_plugin.dll;innodb_lock_waits=ha_innodb_plugin.dll;
innodb_cmp=ha_innodb_plugin.dll;innodb_cmp_reset=ha_innodb_plugin.dll;
innodb_cmpmem=ha_innodb_plugin.dll;innodb_cmpmem_reset=ha_innodb_plugin.dll

After the above, you’ll notice the following new tables in Information Schema:

mysql> SHOW TABLES IN INFORMATION_SCHEMA LIKE 'INNODB_%';
+-----------------------------------------+
| Tables_in_information_schema (INNODB_%) |
+-----------------------------------------+
| INNODB_CMP_RESET                        |
| INNODB_TRX                              |
| INNODB_CMPMEM_RESET                     |
| INNODB_LOCK_WAITS                       |
| INNODB_CMPMEM                           |
| INNODB_CMP                              |
| INNODB_LOCKS                            |
+-----------------------------------------+
7 rows in set (0.00 sec)

For this particular problem, I wanted to see what was in INNODB_TRX, INNODB_LOCKS, and INNODB_LOCK_WAITS:

mysql> SELECT * FROM INFORMATION_SCHEMA.INNODB_TRX; +--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+ | trx_id | trx_state | trx_started | trx_requested_lock_id | trx_wait_started | trx_weight | trx_mysql_thread_id | trx_query | +--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+ | 124616 | LOCK WAIT | 2010-06-23 13:51:52 | 124616:1301:1572:6 | 2010-06-23 13:51:52 | 2 | 496854 | NULL | | 123900 | RUNNING | 2010-06-23 09:30:59 | NULL | NULL | 506 | 3 | NULL | +--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+ 2 rows in set (0.00 sec)


mysql> SELECT * FROM INFORMATION_SCHEMA.INNODB_LOCKS;

+--------------------+-------------+-----------+-----------+-------------------------+------------+------------+-----------+----------+-----------+

| lock_id            | lock_trx_id | lock_mode | lock_type | lock_table              | lock_index | lock_space | lock_page | lock_rec | lock_data |

+--------------------+-------------+-----------+-----------+-------------------------+------------+------------+-----------+----------+-----------+

| 124616:1301:1572:6 | 124616      | X         | RECORD    | `db1`.`t1` | `PRIMARY`  |       1301 |      1572 |        6 | 4100      |

| 123900:1301:1572:6 | 123900      | S         | RECORD    | `db1`.`t1` | `PRIMARY`  |       1301 |      1572 |        6 | 4100      |

+--------------------+-------------+-----------+-----------+-------------------------+------------+------------+-----------+----------+-----------+

2 rows in set (0.01 sec)

mysql> SELECT * FROM INFORMATION_SCHEMA.INNODB_LOCK_WAITS; +-------------------+--------------------+-----------------+--------------------+ | requesting_trx_id | requested_lock_id | blocking_trx_id | blocking_lock_id | +-------------------+--------------------+-----------------+--------------------+ | 124616 | 124616:1301:1572:6 | 123900 | 123900:1301:1572:6 | +-------------------+--------------------+-----------------+--------------------+ 1 row in set (0.00 sec)

Finally, I had conclusive evidence that it was indeed the replication thread (trx id 123900) holding the lock which was blocking the UPDATE.

I also found the exact row which was being held, and all of the details, such as it was a S (shared) record lock, and the the lock was on the primary key of table db1.t1. It even tells you the lock_space (1301), the lock_page (1572), the lock_rec (6) , and the actual data, lock_data (4100).

The other key piece was the time (or trx_started) for the running transaction, 123900. With that, we knew exactly where to check the binlogs for the exact statement where this all began.

In conclusion, I wish I had started here to begin with, so keep this in mind for the future. And this is just one example of how beneficial these new InnoDB Plugin Information Schema tables can be for troubleshooting. You can find even more details/examples at the following location:

http://dev.mysql.com/doc/innodb-plugin/1.0/en/innodb-information-schema-examples.html

Click here to give this article a “Thumbs Up” on Planet MySQL !

Tags: information schema, innodb, innodb information schema, innodb lock monitor, innodb plugin, INNODB_LOCKS, INNODB_LOCK_WAITS, INNODB_TRX, MySQL
Posted in MySQL | 2 Comments »

Writing output to a log file using MySQL Proxy

Monday, November 30th, 2009

In my previous post, Capturing Erroneous Queries with MySQL Proxy, I showed how to capture erroneous queries, along with relevant information, that one could not effectively obtain from the MySQL general query log. However, in that post, I simply output the information to the terminal. Therefore, in this example, I want to show how to write this information to a proxy log file.

To change this to log to a log file does not require too many changes, and so this is a useful example on how to log any proxy-related information to a log file.

I perform a check for an existing log file (at least using the variable of name “log_file”), and then assign log_file to the location of where I want the log file to reside (at the beginning of the lua script).
```
if (log_file == nil) then
  log_file = "C:/Program Files/MySQL/mysql-proxy-0.7.2/proxy.log"
end
```
Directly after that, and a key element, is to then declare a file handle for this file and open it for writing purposes (directly after the above statements):
```
local fh = io.open(log_file, "a+")
```
I create a local variable named “out_string” and assign all output that I want to write to this variable.
Once you have “out_string” fully populated, then just issue the following two commands:
```
fh:write(out_string .. "\n")
fh:flush()
```

Now everything you have stored in the variable “out_string” will be written to the new proxy log file that you have opened.

Here is the full script for reference:

if (log_file == nil) then
  log_file = "C:/Program Files/MySQL/mysql-proxy-0.7.2/proxy.log"
end
local fh = io.open(log_file, "a+")

function read_query( packet )
  if string.byte(packet) == proxy.COM_QUERY then
    proxy.queries:append(1, packet, {resultset_is_needed = true} )
    local out_string = "+ ---------- Incoming query ---------- " .. "\n" ..
      "+ Query = " .. string.sub(packet, 2) .. "\n" ..
      "+ Time  = " .. os.date('%Y-%m-%d %H:%M:%S') .. "\n" ..
      "+ ------------------------------------ "
    fh:write(out_string .. "\n")
    fh:flush()
    return proxy.PROXY_SEND_QUERY
  end
end

function read_query_result (inj)
  local res = assert(inj.resultset)
  if res.query_status == proxy.MYSQLD_PACKET_ERR then
    local out_string = "---------- Returning results ----------" .. "\n" ..
      "- time stamp = "
        .. os.date('%Y-%m-%d %H:%M:%S') .. "\n" ..
      "- query = "
        .. inj.query .. "\n" ..
      "- result.err.code = "
        .. res.raw:byte(2) + (res.raw:byte(3) * 256) .. "\n" ..
      "- result.err.sql_state = "
        .. string.format("%q", res.raw:sub(5, 9)) .. "\n" ..
      "- result.err.msg = "
        .. string.format("%q", res.raw:sub(10)) .. "\n" ..
      "- proxy.connection.client.default_db = "
        .. proxy.connection.client.default_db .. "\n" ..
      "- proxy.connection.client.username = "
        .. proxy.connection.client.username .. "\n" ..
      "- proxy.connection.client.address = "
        .. proxy.connection.client.src.name .. "\n" ..
      "- proxy.connection.server.thread_id = "
        .. proxy.connection.server.thread_id .. "\n"
    fh:write(out_string .. "\n")
    fh:flush()
  end
end

Tags: log file, logging, MySQL, mysql proxy, proxy log file
Posted in MySQL | 5 Comments »

Chris on MySQL

Posts Tagged ‘MySQL’

Using EXPLAIN EXTENDED / SHOW WARNINGS to Help Troubleshoot Inefficient Queries in MySQL

Click here to give this article a “Thumbs Up” on Planet MySQL !

Ease of Switching to the InnoDB Plugin and the Numerous Benefits

Click here to give this article a “Thumbs Up” on Planet MySQL !

Debugging InnoDB Locks using the new InnoDB Plugin’s Information Schema Tables

Click here to give this article a “Thumbs Up” on Planet MySQL !

Writing output to a log file using MySQL Proxy

Pages

Archives

Categories