Slow query logs

Since you can directly have the query log the output of the explain command in MariaDB 10.0.5, this will help you save time. To make it active, you need to add this line in your MariaDB configuration file (/etc/mysql/my.cnf):

[mysqld]
log_slow_verbosity      = query_plan,explain

Then, restart MariaDB. To test it, simply force the creation of a long query. Here is a SQL script with a loop. Adapt the first line if the default time is not enough:

-- Change this value to a higher one if you need more time
-- This will insert x lines number in your database
SET @MAX_INSERT = 100000;

-- Vars
SET SQL_MODE="NO_AUTO_VALUE_ON_ZERO";
SET time_zone = "+00:00";

-- Create database
DROP DATABASE IF EXISTS chapter2;
CREATE DATABASE chapter2;
USE chapter2;

-- Create table and add index
CREATE TABLE IF NOT EXISTS `s_explain` (
 `id` int(11) DEFAULT NULL,
 `ts` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' ON UPDATE CURRENT_TIMESTAMP
) ENGINE=InnoDB DEFAULT CHARSET=latin1;
ALTER TABLE `s_explain` ADD INDEX ( `id` ); 

-- Create a procedure to insert lines
DELIMITER $$
DROP PROCEDURE IF EXISTS proc_name$$
CREATE PROCEDURE proc_name()
BEGIN
 DECLARE count INT DEFAULT 0;
 WHILE count < @MAX_INSERT DO
 SET count = count + 1;
 INSERT INTO `s_explain`(`id`, `ts`) VALUES (FLOOR(RAND() * @MAX_INSERT), NOW());
 END WHILE;
END$$
DELIMITER ;

-- Call procedure
call proc_name();

You can now simply call this script by slowing down the long_query_time, calling the loop.sql script, and running a SELECT command on it:

mysql < loop.sql

Here is the result you will find in your slow query logs:

# Time: 140113 23:02:57
# User@Host: root[root] @ localhost []
# Thread_id: 65 Schema: chapter2 QC_hit: No
# Query_time: 0.254088 Lock_time: 0.000090 Rows_sent: 60000 Rows_examined: 60000
# Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
#
# explain: id select_type table type possible_keys key key_len ref rows Extra
# explain: 1 SIMPLE s_explain ALL NULL NULL NULL NULL 60249
#
SET timestamp=1389654177;
select * from s_explain;

Here is some more information:

• Query_time: This indicates the time taken for the query to run. It's important to check the Lock_time value as well to avoid table locking, which then could block other requests. The query time should be much bigger than the lock time.
• Rows_examined: The lesser the rows examined, the shorter the time the query will take. You can use an index to reduce this time. Rows_examined should be much bigger than Rows_sent in most cases.
• Query_plan: This gives the information from Full_scan to Merge_passes. It should also give important information that helps you understand where a query spends too much time.

This information is just the first step for investigation. You need to dive more into your SQL query or the application that creates the SQL query.