MySQL Forums
Forum List  »  Performance

slow query sorting result - sending data
Posted by: Hugo Rodriguez
Date: April 28, 2015 07:27PM

I have a big performance issue when executing a simple query.
The query is very slow the first time it is executed.
In profile you can see high values in the "CONTEXT_VOLUNTARY, CONTEXT_INVOLUNTARY, BLOCK_OPS_IN, BLOCK_OPS_OUT" columns for the status "sorting result" or "sending data".

Table information:

SHOW CREATE TABLE tableTest;
Table;Create Table
tableTest;CREATE TABLE `tableTest` (
`field_1` varchar(128) NOT NULL,
`field_2` smallint(6) NOT NULL,
`field_3` varchar(128) NOT NULL,
`field_4` datetime default NULL,
`field_5` datetime default NULL,
`field_6` varchar(4) default NULL,
`field_7` varchar(32) default NULL,
`field_8` varchar(128) default NULL,
`field_9` varchar(128) default NULL,
`field_10` varchar(128) default NULL,
`field_11` varchar(128) default NULL,
`field_12` varchar(5) default NULL,
`field_13` varchar(20) default NULL,
`field_14` varchar(8) default NULL,
`field_15` varchar(8) default NULL,
`field_16` varchar(20) default NULL,
`field_17` varchar(8) default NULL,
`field_18` varchar(8) default NULL,
`field_19` varchar(12) default NULL,
`field_20` varchar(12) default NULL,
`field_21` varchar(12) default NULL,
`field_22` varchar(12) default NULL,
`field_23` varchar(7) default NULL,
`field_24` varchar(18) default NULL,
`field_25` varchar(4) default NULL,
`field_26` varchar(6144) default NULL,
`field_27` varchar(6144) default NULL,
KEY `i_tableTest_UPD` (`field_1`,`field_2`,`field_3`,`field_9`,`field_8`,`field_7`,`field_10`,`field_11`),
KEY `i_tableTest_SEL` (`field_7`,`field_11`,`field_8`,`field_9`,`field_12`),
KEY `i_tableTest_o1` (`field_1.`,`field_2`,`field_3`,`field_7`,`field_11`,`field_9`,`field_8`,`field_10`),
KEY `i_tableTest_o2` (`field_1`,`field_2`,`field_3`,`field_7`,`field_11`,`field_9`,`field_8`,`field_12`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

SHOW TABLE STATUS LIKE 'tableTest';
Name;Engine;Version;Row_format;Rows;Avg_row_length;Data_length;Max_data_length;Index_length;Data_free;Auto_increment;Create_time;Update_time;Check_time;Collation;Checksum;Create_options;Comment
tableTest;InnoDB;10;Compact;11557005;2027;23426318336;0;4000464896;0;\N;2014-10-27 18:48:06;\N;\N;latin1_swedish_ci;\N;;InnoDB free: 273408 kB

Variables:

SHOW VARIABLES LIKE "%version%";
Variable_name;Value
protocol_version;10
version;5.0.67
version_comment;SUSE MySQL RPM
version_compile_machine;x86_64
version_compile_os;suse-linux-gnu

SHOW VARIABLES LIKE '%_buffer_%';
Variable_name;Value
bulk_insert_buffer_size;8388608
innodb_buffer_pool_awe_mem_mb;0
innodb_buffer_pool_size;268435456
innodb_log_buffer_size;1048576
join_buffer_size;671088640
key_buffer_size;671088640
myisam_sort_buffer_size;8388608
net_buffer_length;16384
preload_buffer_size;32768
read_buffer_size;268435456
read_rnd_buffer_size;262144
sort_buffer_size;536870912

SHOW VARIABLES LIKE '%query_cache%';
Variable_name;Value
have_query_cache;YES
query_cache_limit;1048576
query_cache_min_res_unit;4096
query_cache_size;0
query_cache_type;ON
query_cache_wlock_invalidate;OFF

Memory:

free -m
total used free shared buffers cached
Mem: 14343 14270 73 0 193 10197
-/+ buffers/cache: 3879 10464
Swap: 0 0 0


Well, the test is the next:

First time query

SELECT
field_6,
field_7,
field_8,
field_9,
field_20,
field_13,
field_14,
field_15,
field_16,
field_17,
field_18,
field_23,
field_24,
field_19
FROM tableTest
WHERE (field_7 = '210010'
OR field_7 = '210020'
OR field_7 = '500001'
OR field_7 = '500002'
OR field_7 = '230010'
OR field_7 = '230020'
OR field_7 = '590001'
OR field_7 = '590002'
OR field_7 = '660000'
OR field_7 = '670000')
AND field_11 = 'XXX'
AND ((field_9 = '20150427'
AND field_8 > '152201')
OR (field_9 > '20150427'))
AND field_12 = '000'
ORDER BY field_9, field_8, field_6 ASC;

/* Affected rows: 0 Filas encontradas: 62 Advertencias: 0 Duración para 1 query: 00:02:40 */

EXPLAIN query1;
id;select_type;table;type;possible_keys;key;key_len;ref;rows;Extra
1;SIMPLE;tableTest;range;i_tableTest_SEL;i_tableTest_SEL;166;\N;35219;Using where; Using filesort

SHOW PROFILE ALL FOR query 1;
Status;Duration;CPU_user;CPU_system;Context_voluntary;Context_involuntary;Block_ops_in;Block_ops_out;Messages_sent;Messages_received;Page_faults_major;Page_faults_minor;Swaps;Source_function;Source_file;Source_line
starting;0.000123;0.000000;0.000000;0;0;0;0;0;0;0;0;0;\N;\N;\N
Opening tables;0.000067;0.000000;0.000000;0;0;0;0;0;0;0;0;0;open_tables;../../sql/sql_base.c;2661
System lock;0.000044;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_lock_tables;../../sql/lock.cc;153
Table lock;0.000044;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_lock_tables;../../sql/lock.cc;163
init;0.000090;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2261
optimizing;0.000062;0.000000;0.000000;0;0;0;0;0;0;0;0;0;optimize;../../sql/sql_select;749
statistics;0.007664;0.000000;0.000000;2;0;64;0;0;0;0;0;0;optimize;../../sql/sql_select;902
preparing;0.000066;0.000000;0.000000;0;0;0;0;0;0;0;0;0;optimize;../../sql/sql_select;912
executing;0.000043;0.000000;0.000000;0;0;0;0;0;0;0;0;0;exec;../../sql/sql_select;1581
Sorting result;160.667493;2.924183;0.584037;25636;1597;1116448;35112;0;0;0;1416;0;exec;../../sql/sql_select;1977
Sending data;0.000319;0.000000;0.000000;0;0;0;0;0;0;0;0;0;exec;../../sql/sql_select;2101
end;0.000057;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2306
end;0.000043;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2308
query end;0.000040;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_execute_command;../../sql/sql_parse.;5276
freeing items;0.000057;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_parse;../../sql/sql_parse.;6279
closing tables;0.000045;0.000000;0.000000;0;0;0;0;0;0;0;0;0;dispatch_command;../../sql/sql_parse.;2237
logging slow query;0.000039;0.000000;0.000000;0;0;0;0;0;0;0;0;0;log_slow_statement;../../sql/sql_parse.;2295
logging slow query;0.000039;0.000000;0.000000;0;0;0;0;0;0;0;0;0;log_slow_statement;../../sql/sql_parse.;2305
cleaning up;0.000042;0.000000;0.000000;0;0;0;0;0;0;0;0;0;dispatch_command;../../sql/sql_parse.;2260

Slow sorting result phase


Second time same query

SELECT
field_6,
field_7,
field_8,
field_9,
field_20,
field_13,
field_14,
field_15,
field_16,
field_17,
field_18,
field_23,
field_24,
field_19
FROM tableTest
WHERE (field_7 = '210010'
OR field_7 = '210020'
OR field_7 = '500001'
OR field_7 = '500002'
OR field_7 = '230010'
OR field_7 = '230020'
OR field_7 = '590001'
OR field_7 = '590002'
OR field_7 = '660000'
OR field_7 = '670000')
AND field_11 = 'XXX'
AND ((field_9 = '20150427'
AND field_8 > '152201')
OR (field_9 > '20150427'))
AND field_12 = '000'
ORDER BY field_9, field_8, field_6 ASC;

/* Affected rows: 0 Filas encontradas: 62 Advertencias: 0 Duración para 1 query: 2,075 sec. */

EXPLAIN query2;
id;select_type;table;type;possible_keys;key;key_len;ref;rows;Extra
1;SIMPLE;tableTest;range;i_tableTest_SEL;i_tableTest_SEL;166;\N;35219;Using where; Using filesort

SHOW PROFILE ALL FOR query 2;
Status;Duration;CPU_user;CPU_system;Context_voluntary;Context_involuntary;Block_ops_in;Block_ops_out;Messages_sent;Messages_received;Page_faults_major;Page_faults_minor;Swaps;Source_function;Source_file;Source_line
starting;0.000124;0.000000;0.000000;0;0;0;0;0;0;0;0;0;\N;\N;\N
Opening tables;0.000053;0.000000;0.000000;0;0;0;0;0;0;0;0;0;open_tables;../../sql/sql_base.c;2661
System lock;0.000043;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_lock_tables;../../sql/lock.cc;153
Table lock;0.000046;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_lock_tables;../../sql/lock.cc;163
init;0.000090;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2261
optimizing;0.000064;0.000000;0.000000;0;0;0;0;0;0;0;0;0;optimize;../../sql/sql_select;749
statistics;0.000756;0.000000;0.000000;0;0;0;0;0;0;0;0;0;optimize;../../sql/sql_select;902
preparing;0.000068;0.000000;0.000000;0;0;0;0;0;0;0;0;0;optimize;../../sql/sql_select;912
executing;0.000044;0.000000;0.000000;0;0;0;0;0;0;0;0;0;exec;../../sql/sql_select;1581
Sorting result;2.079908;1.264079;0.268016;171;165;1168;88;0;0;0;1261;0;exec;../../sql/sql_select;1977
Sending data;0.000343;0.000000;0.000000;0;0;0;0;0;0;0;0;0;exec;../../sql/sql_select;2101
end;0.000049;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2306
end;0.000050;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2308
query end;0.000042;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_execute_command;../../sql/sql_parse.;5276
freeing items;0.000058;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_parse;../../sql/sql_parse.;6279
closing tables;0.000045;0.000000;0.000000;0;0;0;0;0;0;0;0;0;dispatch_command;../../sql/sql_parse.;2237
logging slow query;0.000040;0.000000;0.000000;0;0;0;0;0;0;0;0;0;log_slow_statement;../../sql/sql_parse.;2295
cleaning up;0.000042;0.000000;0.000000;0;0;0;0;0;0;0;0;0;dispatch_command;../../sql/sql_parse.;2260

The query is faster than the first time.


Aditional test:

Query without order by (changing a value on the where conditions)

SELECT
field_6,
field_7,
field_8,
field_9,
field_20,
field_13,
field_14,
field_15,
field_16,
field_17,
field_18,
field_23,
field_24,
field_19
FROM tableTest
WHERE (field_7 = '210010'
OR field_7 = '210020'
OR field_7 = '500001'
OR field_7 = '500002'
OR field_7 = '230010'
OR field_7 = '230020'
OR field_7 = '590001'
OR field_7 = '590002'
OR field_7 = '660000'
OR field_7 = '670000')
AND field_11 = 'ZZZ'
AND ((field_9 = '20150427'
AND field_8 > '152201')
OR (field_9 > '20150427'))
AND field_12 = '000';

/* Affected rows: 0 Filas encontradas: 55 Advertencias: 0 Duración para 1 query: 00:01:39 */

EXPLAIN query3;
id;select_type;table;type;possible_keys;key;key_len;ref;rows;Extra
1;SIMPLE;tableTest;range;i_tableTest_SEL;i_tableTest_SEL;166;\N;31363;Using where

SHOW PROFILE ALL FOR query 3;
Status;Duration;CPU_user;CPU_system;Context_voluntary;Context_involuntary;Block_ops_in;Block_ops_out;Messages_sent;Messages_received;Page_faults_major;Page_faults_minor;Swaps;Source_function;Source_file;Source_line
starting;0.000125;0.000000;0.000000;0;0;0;0;0;0;0;0;0;\N;\N;\N
Opening tables;0.000053;0.000000;0.000000;0;0;0;0;0;0;0;0;0;open_tables;../../sql/sql_base.c;2661
System lock;0.000042;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_lock_tables;../../sql/lock.cc;153
Table lock;0.000044;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_lock_tables;../../sql/lock.cc;163
init;0.000088;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2261
optimizing;0.000063;0.000000;0.000000;0;0;0;0;0;0;0;0;0;optimize;../../sql/sql_select;749
statistics;0.054307;0.004000;0.000000;7;0;448;0;0;0;0;0;0;optimize;../../sql/sql_select;902
preparing;0.000133;0.000000;0.000000;0;0;0;0;0;0;0;0;0;optimize;../../sql/sql_select;912
executing;0.000043;0.000000;0.000000;0;0;0;0;0;0;0;0;0;exec;../../sql/sql_select;1581
Sending data;99.489397;1.748109;0.336021;15440;156;731328;16312;0;0;0;51;0;exec;../../sql/sql_select;2101
end;0.000191;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2306
end;0.000041;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_select;../../sql/sql_select;2308
query end;0.000040;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_execute_command;../../sql/sql_parse.;5276
freeing items;0.000053;0.000000;0.000000;0;0;0;0;0;0;0;0;0;mysql_parse;../../sql/sql_parse.;6279
closing tables;0.000044;0.000000;0.000000;0;0;0;0;0;0;0;0;0;dispatch_command;../../sql/sql_parse.;2237
logging slow query;0.000039;0.000000;0.000000;0;0;0;0;0;0;0;0;0;log_slow_statement;../../sql/sql_parse.;2295
logging slow query;0.000039;0.000000;0.000000;0;0;0;0;0;0;0;0;0;log_slow_statement;../../sql/sql_parse.;2305
cleaning up;0.000041;0.000000;0.000000;0;0;0;0;0;0;0;0;0;dispatch_command;../../sql/sql_parse.;2260

Slow sending data phase.


Thanks,

Hugh

Options: ReplyQuote


Subject
Views
Written By
Posted
slow query sorting result - sending data
3097
April 28, 2015 07:27PM


Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.