Bug #76996 Querys with order by may fail because read_rnd_buffer_size is too small
Submitted: 11 May 2015 9:13 Modified: 11 May 2015 11:42
Reporter: zhang yingqiang (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S3 (Non-critical)
Version:5.6.16 5.7.7, 5.6.24 OS:Linux
Assigned to: CPU Architecture:Any
Tags: order by; temp file; read_rnd_buffer_size;

[11 May 2015 9:13] zhang yingqiang
Description:
Function rr_from_cache is used to avoid disk seeks in order by with temp file.
But if the reclength is to big, that we can only cache equal or less than 2 records in the  read_rnd_buffer_size, mysql will renounce the use of rr_from_cache. 
In this case, "if (info->cache_records <= 2" branch (in init_rr_cache), return 1(fail) without set error.
In debug version, mysqld will crash at Protocol::end_statement, In release version, client will report error 2027 "Malformed packet"

How to repeat:
show global variables like 'read_rnd_buffer_size';
show global variables like 'sort_buffer_size';
set session read_rnd_buffer_size = 128*1024;
show session variables like 'read_rnd_buffer_size';

create table t1(id int auto_increment primary key, v1 varchar(10000),v2 varchar(10000), a int) engine=innodb default charset=utf8;
insert into t1 select null,repeat('a',8000),repeat('a',8000),1;
insert into t1 select null, v1, v2, a from t1;
insert into t1 select null, v1, v2, a from t1;
insert into t1 select null, v1, v2, a from t1;
insert into t1 select null, v1, v2, a from t1;
insert into t1 select null, v1, v2, a from t1;
insert into t1 select null, v1, v2, a from t1;
insert into t1 select null, v1, v2, a from t1;
insert into t1 select null, v1, v2, a from t1;
insert into t1 select null, v1, v2, a from t1;

select count(1) from t1;
update t1 set a=id%4;
select id,a from t1 limit 10;
select * from t1 order by a,v1 limit 500, 2;

#clean up
drop table t1;

Suggested fix:
diff --git a/sql/records.cc b/sql/records.cc
index 81322ee..33870c8 100644
--- a/sql/records.cc
+++ b/sql/records.cc
@@ -256,7 +256,9 @@ bool init_read_record(READ_RECORD *info,THD *thd, TABLE *table,
        info->io_cache->end_of_file/info->ref_length * table->s->reclength >
        (my_off_t) MIN_ROWS_TO_USE_TABLE_CACHE &&
        !table->s->blob_fields &&
-        info->ref_length <= MAX_REFLENGTH)
+        info->ref_length <= MAX_REFLENGTH &&
+       (thd->variables.read_rnd_buff_size /
+               (ALIGN_SIZE(info->table->s->reclength+1)+3+MAX_REFLENGTH)) > 2)
     {
       if (init_rr_cache(thd, info))
         DBUG_RETURN(true);
[11 May 2015 10:25] Umesh Shastry
Hello zhang yingqiang,
 
Thank you for the bug report and test case.
Observed this behavior with 5.6.24.

Thanks,
Umesh
[11 May 2015 10:26] Umesh Shastry
// 5.6.24

scripts/mysql_install_db --basedir=/export/umesh/server/binaries/mysql-5.6.24 --datadir=/export/umesh/server/binaries/mysql-5.6.24/76996
bin/mysqld --basedir=/export/umesh/server/binaries/mysql-5.6.24 --datadir=/export/umesh/server/binaries/mysql-5.6.24/76996 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.24/76996/log.err 2>&1 &

commit: 97543660999308893335d81b92307c389e6821a5
date: 2015-03-25 17:22:45 +0100
build-date: 2015-03-25 17:26:48 +0100
short: 9754366
branch: mysql-5.6.24-release

MySQL source 5.6.24

// release build

mysql> select * from t1 order by a,v1 limit 500, 2;
ERROR 2027 (HY000): Malformed packet
mysql>
mysql> #clean up
mysql> drop table t1;
Query OK, 0 rows affected (0.03 sec)

// debug build

(gdb) bt
#0  0x00007f233b92b771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000ae0f7f in my_write_core (sig=6) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/mysys/stacktrace.c:422
#2  0x0000000000745f8a in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007f233a5315c9 in raise () from /lib64/libc.so.6
#5  0x00007f233a532cd8 in abort () from /lib64/libc.so.6
#6  0x00007f233a52a536 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007f233a52a5e2 in __assert_fail () from /lib64/libc.so.6
#8  0x000000000073d36d in Protocol::end_statement (this=0x39d4a98) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/protocol.cc:518
#9  0x00000000008051a9 in dispatch_command (command=COM_QUERY, thd=0x39d45c0, packet=0x3b04df1 "", packet_length=43)
    at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/sql_parse.cc:1770
#10 0x00000000008056c0 in do_command (thd=0x39d45c0) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/sql_parse.cc:1037
#11 0x00000000007bb221 in do_handle_one_connection (thd_arg=0x39d45c0) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/sql_connect.cc:982
#12 0x00000000007bb2e7 in handle_one_connection (arg=0x39d45c0) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/sql_connect.cc:898
#13 0x0000000000dd43e0 in pfs_spawn_thread (arg=0x3ae6ad0) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/storage/perfschema/pfs.cc:1860
#14 0x00007f233b926df3 in start_thread () from /lib64/libpthread.so.0
#15 0x00007f233a5f247d in clone () from /lib64/libc.so.6
(gdb)
[11 May 2015 11:24] Umesh Shastry
// 5.7.7

bin/mysql_install_db  --insecure --basedir=/export/umesh/server/binaries/mysql-5.7.7 --datadir=/export/umesh/server/binaries/mysql-5.7.7/76996
bin/mysqld --basedir=/export/umesh/server/binaries/mysql-5.7.7 --datadir=/export/umesh/server/binaries/mysql-5.7.7/76996 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.7.7/76996/log.err 2>&1 &

commit: 103058393f8a69e633a88ff06927846a74de61ef
date: 2015-03-30 14:04:32 +0200
build-date: 2015-03-30 14:06:25 +0200
short: 1030583
branch: mysql-5.7.7-rc-release

MySQL source 5.7.7

// release build

mysql> select * from t1 order by a,v1 limit 500, 2;
ERROR 2027 (HY000): Malformed packet

// debug build

(gdb) bt
#0  0x00007ff4872a3771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000001811321 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-14853600-1427719770.96/mysql-5.7.7-rc/mysys/stacktrace.c:247
#2  0x0000000000e33b08 in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-14853600-1427719770.96/mysql-5.7.7-rc/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007ff485ea95c9 in raise () from /lib64/libc.so.6
#5  0x00007ff485eaacd8 in abort () from /lib64/libc.so.6
#6  0x00007ff485ea2536 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007ff485ea25e2 in __assert_fail () from /lib64/libc.so.6
#8  0x00000000014107e1 in Protocol::end_statement (this=0x7ff40c0010d0) at /export/home/pb2/build/sb_0-14853600-1427719770.96/mysql-5.7.7-rc/sql/protocol.cc:663
#9  0x00000000014e34ec in dispatch_command (command=COM_QUERY, thd=0x7ff40c000bb0, packet=0x7ff40c009d61 "", packet_length=43)
    at /export/home/pb2/build/sb_0-14853600-1427719770.96/mysql-5.7.7-rc/sql/sql_parse.cc:1675
#10 0x00000000014e0ab5 in do_command (thd=0x7ff40c000bb0) at /export/home/pb2/build/sb_0-14853600-1427719770.96/mysql-5.7.7-rc/sql/sql_parse.cc:835
#11 0x000000000160d271 in handle_connection (arg=0x3aa2300) at /export/home/pb2/build/sb_0-14853600-1427719770.96/mysql-5.7.7-rc/sql/conn_handler/connection_handler_per_thread.cc:298
#12 0x0000000001bcc512 in pfs_spawn_thread (arg=0x3c744e0) at /export/home/pb2/build/sb_0-14853600-1427719770.96/mysql-5.7.7-rc/storage/perfschema/pfs.cc:2147
#13 0x00007ff48729edf3 in start_thread () from /lib64/libpthread.so.0
#14 0x00007ff485f6a47d in clone () from /lib64/libc.so.6
[11 May 2015 11:25] Umesh Shastry
I'm not able to reproduce this on latest 5.6 builds(5.6.26) and 5.7.8(and trunk 5.8.0)
[11 May 2015 11:28] Tor Didriksen
Duplicate of internal

Bug#20895852 UNDERSIZED TMP_TABLE_SIZE - ASSERTION OR ERROR
 2027 (HY000): MALFORMED PACKET

Fixed in 5.6.25
[11 May 2015 11:28] Umesh Shastry
In order for us to accept your contribution you need to sign Oracle Contributor Agreement as described in the "Contributions" tab of this bug report. Please see the following for more details:

http://www.oracle.com/technetwork/community/oca-486395.html
[11 May 2015 11:42] Umesh Shastry
Thank you Tor for confirming.
Indeed, this is duplicate of internal bug Bug#20895852 which is fixed.

Noted in 5.6.25, 5.7.8, 5.8.0 changelogs. 

For small values of the read_rnd_buffer_size system variable, 
internal caching of temporary results could fail and cause query 
execution failure.
[10 Jun 2015 12:59] Umesh Shastry
Bug #77298 marked as duplicate of this
[24 Jun 2015 4:47] Laurynas Biveinis
commit 103f64dfd0e3fe8bf39fcf578f9946893b3c4457
Author: Tor Didriksen <tor.didriksen@oracle.com>
Date:   Fri Apr 17 13:00:37 2015 +0200

    Bug#20895852 UNDERSIZED TMP_TABLE_SIZE - ASSERTION OR ERROR 2027 (HY000): MALFORMED PACKET
    
    Problem: Internal caching of temporary results depends on the buffer size
    determined by the variable read_rnd_buffer_size. If this value is too small,
    we fail to execute the query.
    
    Fix: Ignore the error if we cannot cache intermediate results,
    and read directly from the temporary file.