MySQL Bugs: #36022: please log more information about "Sort aborted" queries

Bug #36022	please log more information about "Sort aborted" queries
Submitted:	13 Apr 2008 8:17	Modified:	2 Mar 2011 3:04
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Errors	Severity:	S4 (Feature request)
Version:	5.0, 5.1, 5.5, 6.0	OS:	Any
Assigned to:	Tor Didriksen	CPU Architecture:	Any
Tags:	sort aborted

Description:
This is a feature request to add more verbose logging for this message:

080413  9:23:17 [ERROR] mysqld-nt: Sort aborted
080413  9:23:36 [ERROR] mysqld-nt: Sort aborted
080413  9:23:58 [ERROR] mysqld-nt: Sort aborted

There are some known causes, such as :

o) insufficient disk space in tmpdir prevented tmpfile from being created
o) insufficient memory for sort_buffer_size to be allocated
o) somebody ran KILL <id> in the middle of a filesort
o) the server was shutdown while some queries were sorting
o) a transaction got rolled back or aborted due to lock wait timeout or deadlock 
o) unexpected errors, such as source table or even tmp table was corrupt
o) processing of a subquery failed which was also sorting, see 'how to repeat'

In the case of out of memory or transaction rollback, I think there is another message printed, but still not enough details. 

How to repeat:
drop table if exists `t1`;
create table `t1` (`a` int,`b` int) engine=myisam;
insert into `t1` values (2,4),(7,8);
select group_concat(distinct t1.a) a
from t1 where  t1.a = (select a from t1)
group by  b;

on a busy server it can be tough job to find out the above query caused the message in the log file (although it seems like an expected error).

Suggested fix:
It would be good to know what connection id, query (truncated to xxx bytes), and user/host caused it. These details could only be printed when --log-warn=2 is enabled.

Thank you for a feature request.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/129214

3535 Tor Didriksen	2011-01-19
      Bug #36022 please log more information about "Sort aborted" queries
      
      Write an additional warning message to the server log, 
      explaining why a sort operation is aborted.
      
      The output in mysqld.err will look something like:
      [ERROR] bin-dbg/sql/mysqld: Sort aborted
      [Warning] Sort aborted : Out of memory (Needed 24 bytes)
      [ERROR] bin-dbg/sql/mysqld: Out of sort memory; increase server sort buffer size
      [ERROR] bin-dbg/sql/mysqld: Sort aborted
      [Warning] Sort aborted : Out of sort memory; increase server sort buffer size
      [ERROR] bin-dbg/sql/mysqld: Sort aborted
      [Warning] Sort aborted : Incorrect number of arguments for FUNCTION test.f1; expected 0, got 1
     @ include/my_sys.h
        Update comment for ME_NOREFRESH
     @ mysql-test/r/filesort_debug.result
        New test case.
     @ mysql-test/t/filesort_debug.test
        New test case.
     @ sql/filesort.cc
        Output an explanation using the error message from the THD Diagnostics_area.
     @ sql/protocol.cc
        Do not DBUG_RETURN(function_call_with DBUG_RETURN)
        as it messes up the call stack in the debug output.
     @ sql/unireg.h
        Remove unused/confusing ERRMAPP macro.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

http://lists.mysql.com/commits/129220

3535 Tor Didriksen 2011-01-19
Bug #36022 please log more information about "Sort aborted" queries

Write an additional warning message to the server log,
explaining why a sort operation is aborted.

The output in mysqld.err will look something like:
[ERROR] bin-dbg/sql/mysqld: Sort aborted
[Warning] Sort aborted : Out of memory (Needed 24 bytes)
[ERROR] bin-dbg/sql/mysqld: Out of sort memory; increase server sort buffer size
[ERROR] bin-dbg/sql/mysqld: Sort aborted
[Warning] Sort aborted : Out of sort memory; increase server sort buffer size
[ERROR] bin-dbg/sql/mysqld: Sort aborted
[Warning] Sort aborted : Incorrect number of arguments for FUNCTION test.f1; expected 0, got 1

If --log-warn=2 is enabled, we output information about host/user/query as well.
@ include/my_sys.h
Update comment for ME_NOREFRESH
@ mysql-test/r/filesort_debug.result
New test case.
@ mysql-test/t/filesort_debug.test
New test case.
@ sql/filesort.cc
Output an explanation using the error message from the THD Diagnostics_area.
@ sql/protocol.cc
Do not DBUG_RETURN(function_call_with DBUG_RETURN)
as it messes up the call stack in the debug output.
@ sql/unireg.h
Remove unused/confusing ERRMAPP macro.

Please change from "increase server sort buffer size" to "consider increasing server sort buffer size".

We get problems from people using tools that always say increase without considering how big the existing size is and it's good not to add more instructions like that.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/129754

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/130031

Patch approved with minor comments sent by e-mail.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/130205

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/130218

3592 Tor Didriksen	2011-02-02 [merge]
      Merge Bug #36022 from 5.5

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/130220

3593 Tor Didriksen	2011-02-02 [merge]
      Merge Bug #36022 from 5.5

Pushed into mysql-trunk 5.6.2 (revid:tor.didriksen@oracle.com-20110202134110-1uncowbmni6m62kg) (version source revid:tor.didriksen@oracle.com-20110202134110-1uncowbmni6m62kg) (merge vers: 5.6.2) (pib:24)

Pushed into mysql-5.5 5.5.10 (revid:tor.didriksen@oracle.com-20110202115449-lb299za67piiyw2l) (version source revid:tor.didriksen@oracle.com-20110202115449-lb299za67piiyw2l) (merge vers: 5.5.10) (pib:24)

Noted in 5.5.10, 5.6.2 changelogs.

Previously, for queries that were aborted due to sort problem, the
server wrote the message Sort aborted to the error log. Now the
server writes more information to provide a more specific message,
such as: 

[ERROR] mysqld: Sort aborted: Out of memory (Needed 24 bytes)
[ERROR] mysqld: Out of sort memory,
        consider increasing server sort buffer size
[ERROR] mysqld: Sort aborted: Out of sort memory,
        consider increasing server sort buffer size
[ERROR] mysqld: Sort aborted: Incorrect number of arguments for
        FUNCTION test.f1; expected 0, got 1

In addition, if the server was started with --log-warnings=2, the
server write information about the host, user, and query.

CHANGESET - http://lists.mysql.com/commits/130220