Bug #38187 Error 153 when creating savepoints

• Submitted: 16 Jul 2008 22:53
• Modified: 19 Jun 2010 17:47
• Reporter: Gary Pendergast
• Status: Closed
• Category: MySQL Server: InnoDB storage engine
• Severity: S2 (Serious)
• Version: 5.0.60sp1, 5.1.30
• OS: Any
• CPU Architecture: Any

[16 Jul 2008 22:53] Gary Pendergast

Description:
Error occurs when running the SQL below.

How to repeat:
DROP TABLE IF EXISTS foo;
CREATE TABLE `foo` (
  `a` int(11) NOT NULL auto_increment,
  PRIMARY KEY  (`a`)
) ENGINE=InnoDB;

begin;
insert into foo values();
savepoint a1;
insert into foo values();
savepoint a2;
insert into foo values();
savepoint a1;
insert into foo values();
savepoint a2;
show warnings;
rollback;

Suggested fix:
Don't throw that error.

[22 Jul 2008 2:34] Devananda van der Veen

DROP TABLE IF EXISTS foo;
CREATE TABLE `foo` (
  `a` int(11) NOT NULL auto_increment,
  PRIMARY KEY  (`a`)
) ENGINE=InnoDB;

begin;
insert into foo values();
savepoint a1;
insert into foo values();
savepoint a2;
insert into foo values();
savepoint a1;
insert into foo values();
savepoint a2; -- this generates the first warning
insert into foo values();
savepoint z;
select max(a) from foo; -- I expect to see this result in the final step
insert into foo values();
savepoint a1;
insert into foo values();
savepoint a2; -- this generates another warning
select max(a) from foo; -- this is what is actually returned in final step
rollback to z; -- ERROR 1181 (HY000): Got error 153 during ROLLBACK
select max(a) from foo; -- I should get '5' but instead I get '7'
rollback to a1; -- ERROR 1305 (42000): SAVEPOINT a1 does not exist

[23 Jul 2008 18:30] Devananda van der Veen

Tested and confirmed on 5.1.26-rc-community. Only difference is that the steps which in 5.0 generate warnings ('savepoint' after fifth and seventh 'insert') instead generate errors, though the message text is the same. Failure at 'rollback to z' remains unchanged.

[5 Dec 2008 10:22] MySQL Verification Team

5.1.30-debug asserts with testcase:
1401B9F35    mysqld-debug.exe!my_sigabrt_handler()[mysqld.cc:1985]
140736051    mysqld-debug.exe!raise()[winsig.c:597]
140729183    mysqld-debug.exe!abort()[abort.c:78]
1407224F4    mysqld-debug.exe!_wassert()[assert.c:212]
1402B12DC    mysqld-debug.exe!Diagnostics_area::set_ok_status()[sql_class.cc:411]
14020B69E    mysqld-debug.exe!my_ok()[sql_class.h:2244]
140304ABF    mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:4053]
14030AC40    mysqld-debug.exe!mysql_parse()[sql_parse.cc:5791]
1402FC3D8    mysqld-debug.exe!dispatch_command()[sql_parse.cc:1202]
1402FB787    mysqld-debug.exe!do_command()[sql_parse.cc:857]
14044ACB6    mysqld-debug.exe!handle_one_connection()[sql_connect.cc:1115]
14054B205    mysqld-debug.exe!pthread_start()[my_winthread.c:85]
1407387E5    mysqld-debug.exe!_callthreadstart()[thread.c:295]
1407387B7    mysqld-debug.exe!_threadstart()[thread.c:277]
077D6B69A    kernel32.dll!BaseThreadStart()
to get some variables.
inters may be invalid and cause the dump to abort...
ery at 0000000004C806F8=savepoint a2

5.1.30 release build:

mysql> savepoint a2;
ERROR 1030 (HY000): Got error 153 from storage engine
mysql> show warnings;
+-------+------+-----------------------------------+
| Level | Code | Message                           |
+-------+------+-----------------------------------+
| Error | 1030 | Got error 153 from storage engine |
+-------+------+-----------------------------------+
1 row in set (0.02 sec)

[5 Dec 2008 17:46] Mikhail Izioumtchenko

Sunny owns transactions. There's clearly inconsistent treatment
of the savepoints with the same name. It looks like this statement
from the manual doesn't reflect what actually happens:

If the current transaction has a savepoint
with the same name, the old savepoint is deleted and a new one is set.

Regarding the crash Diagnostics_area::set_ok_status(): unrelated problem,
not InnoDB, I see it in other tests [with 5.1.31, though]. 
Workaround: don't use --with-debug configure parameter.

[10 Jan 2009 11:28] Sunny Bains

Hi,

This doesn't seem like a real error at least not within InnoDB. Is
there some documentation that I can consult to determine what the
expected behavior is ?

e.g.,

 savepoint a1;
 savepoint a2;
 savepoint a1; <- This will also delete a2, which is OK
 savepoint a2; <- Here MySQL calls "Delete savepoint a2" which doesn't exist!

Now the question is, should InnoDB return SUCCESS when it can't find the
savepoint a2 to delete. See GDB session below for details.

...
Breakpoint 3, innobase_savepoint (hton=0xd4c710, thd=0x128d890,
    savepoint=0x129ef30) at handler/ha_innodb.cc:2171
2171            int     error = 0;
(gdb) n
2186            trx = check_trx_exists(thd);
(gdb)
2192            innobase_release_stat_resources(trx);
(gdb)
2199            longlong2str((ulint)savepoint,name,36);
(gdb)
2201            error = (int) trx_savepoint_for_mysql(trx, name, (ib_longlong)0);
(gdb) p name
$13 = "BMHWW\000\000\000\2308,\001\000\000\000\000p�(\001\000\000\000\000`t�", '\0' <repeats 13 times>, "`�)\001\000\000\000\000\000�)\001\000\000\000\000\200�(\001\000\000\000"
(gdb) c
Continuing.

Breakpoint 3, innobase_savepoint (hton=0xd4c710, thd=0x128d890,
    savepoint=0x129ef88) at handler/ha_innodb.cc:2171
2171            int     error = 0;
(gdb) n
2186            trx = check_trx_exists(thd);
(gdb)
2192            innobase_release_stat_resources(trx);
(gdb)
2199            longlong2str((ulint)savepoint,name,36);
(gdb)
2201            error = (int) trx_savepoint_for_mysql(trx, name, (ib_longlong)0);
(gdb) p name
$14 = "BMHZC\000\000\000�>\217\000\000\000\000\000p�(\001\000\000\000\000`t�\000\001\000\000\0002\000\000\000\000\000\000\000��)\001\000\000\000\000\000�)\001\000\000\000\000\200�(\001\000\000\000"
(gdb) bt
#0  innobase_savepoint (hton=0xd4c710, thd=0x128d890, savepoint=0x129ef88)
    at handler/ha_innodb.cc:2201
#1  0x00000000006da8a7 in ha_savepoint (thd=0x128d890, sv=0x129ef68)
    at handler.cc:1717
#2  0x00000000005e127a in mysql_execute_command (thd=0x128d890)
    at sql_parse.cc:3933
#3  0x00000000005e370a in mysql_parse (thd=0x128d890,
    inBuf=0x12c3480 "savepoint a2", length=12, found_semicolon=0x43848000)
    at sql_parse.cc:5645
#4  0x00000000005e4356 in dispatch_command (command=COM_QUERY, thd=0x128d890,
    packet=0x12bb451 "savepoint a2", packet_length=12) at sql_parse.cc:1137
#5  0x00000000005e54c9 in do_command (thd=0x128d890) at sql_parse.cc:794
#6  0x00000000005d53e9 in handle_one_connection (arg=0x128d890)
    at sql_connect.cc:1115
#7  0x00002b1f7b7e2f1a in start_thread () from /lib/libpthread.so.0
#8  0x00002b1f7bfa35d2 in clone () from /lib/libc.so.6
#9  0x0000000000000000 in ?? ()
(gdb) c
Continuing.

Breakpoint 2, innobase_release_savepoint (hton=0xd4c710, thd=0x128d890,
    savepoint=0x129ef30) at handler/ha_innodb.cc:2143
2143            int             error = 0;
(gdb) bt
#0  innobase_release_savepoint (hton=0xd4c710, thd=0x128d890,
    savepoint=0x129ef30) at handler/ha_innodb.cc:2143
#1  0x00000000006da799 in ha_release_savepoint (thd=0x128d890, sv=0x129ef10)
    at handler.cc:1747
#2  0x00000000005e11ae in mysql_execute_command (thd=0x128d890)
    at sql_parse.cc:3916
#3  0x00000000005e370a in mysql_parse (thd=0x128d890,
    inBuf=0x12c3480 "savepoint a1", length=12, found_semicolon=0x43848000)
    at sql_parse.cc:5645
#4  0x00000000005e4356 in dispatch_command (command=COM_QUERY, thd=0x128d890,
    packet=0x12bb451 "savepoint a1", packet_length=12) at sql_parse.cc:1137
#5  0x00000000005e54c9 in do_command (thd=0x128d890) at sql_parse.cc:794
#6  0x00000000005d53e9 in handle_one_connection (arg=0x128d890)
    at sql_connect.cc:1115
#7  0x00002b1f7b7e2f1a in start_thread () from /lib/libpthread.so.0
#8  0x00002b1f7bfa35d2 in clone () from /lib/libc.so.6
#9  0x0000000000000000 in ?? ()
(gdb) n
2149            trx = check_trx_exists(thd);
(gdb)
2153            longlong2str((ulint)savepoint, name, 36);
(gdb)
2155            error = (int) trx_release_savepoint_for_mysql(trx, name);
(gdb) p name
$15 = "BMHWW\000\000\0001\000\000\000\000\000\000\000\000�)\001����\000\000\000\000\000\000\000\000\002\000\000\000\000\000\000\000b�)\001\000\000\000\000\002\000\000\000\000\000\000\000\0225,\001\000\000\000"
(gdb) c
Continuing.

Breakpoint 3, innobase_savepoint (hton=0xd4c710, thd=0x128d890,
    savepoint=0x129ef30) at handler/ha_innodb.cc:2171
2171            int     error = 0;
(gdb) bt
#0  innobase_savepoint (hton=0xd4c710, thd=0x128d890, savepoint=0x129ef30)
    at handler/ha_innodb.cc:2171
#1  0x00000000006da8a7 in ha_savepoint (thd=0x128d890, sv=0x129ef10)
    at handler.cc:1717
#2  0x00000000005e127a in mysql_execute_command (thd=0x128d890)
    at sql_parse.cc:3933
#3  0x00000000005e370a in mysql_parse (thd=0x128d890,
    inBuf=0x12c3480 "savepoint a1", length=12, found_semicolon=0x43848000)
    at sql_parse.cc:5645
#4  0x00000000005e4356 in dispatch_command (command=COM_QUERY, thd=0x128d890,
    packet=0x12bb451 "savepoint a1", packet_length=12) at sql_parse.cc:1137
#5  0x00000000005e54c9 in do_command (thd=0x128d890) at sql_parse.cc:794
#6  0x00000000005d53e9 in handle_one_connection (arg=0x128d890)
    at sql_connect.cc:1115
#7  0x00002b1f7b7e2f1a in start_thread () from /lib/libpthread.so.0
#8  0x00002b1f7bfa35d2 in clone () from /lib/libc.so.6
#9  0x0000000000000000 in ?? ()
(gdb) n
2186            trx = check_trx_exists(thd);
(gdb)
2192            innobase_release_stat_resources(trx);
(gdb)
2199            longlong2str((ulint)savepoint,name,36);
(gdb)
2201            error = (int) trx_savepoint_for_mysql(trx, name, (ib_longlong)0);
(gdb) p name
$16 = "BMHWW\000\000\0000�)\001\000\000\000\000\220�(\001\000\000\000\000\020��\000\000\000\000\000BMHWW\000\000\000��)\001\000\000\000\000\000�)\001\000\000\000\000\200�(\001\000\000\000"
(gdb) c
Continuing.

Breakpoint 2, innobase_release_savepoint (hton=0xd4c710, thd=0x128d890,
    savepoint=0x129ef88) at handler/ha_innodb.cc:2143
2143            int             error = 0;
(gdb) bt
#0  innobase_release_savepoint (hton=0xd4c710, thd=0x128d890,
    savepoint=0x129ef88) at handler/ha_innodb.cc:2143
#1  0x00000000006da799 in ha_release_savepoint (thd=0x128d890, sv=0x129ef68)
    at handler.cc:1747
#2  0x00000000005e11ae in mysql_execute_command (thd=0x128d890)
    at sql_parse.cc:3916
#3  0x00000000005e370a in mysql_parse (thd=0x128d890,
    inBuf=0x12c3480 "savepoint a2", length=12, found_semicolon=0x43848000)
    at sql_parse.cc:5645
#4  0x00000000005e4356 in dispatch_command (command=COM_QUERY, thd=0x128d890,
    packet=0x12bb451 "savepoint a2", packet_length=12) at sql_parse.cc:1137
#5  0x00000000005e54c9 in do_command (thd=0x128d890) at sql_parse.cc:794
#6  0x00000000005d53e9 in handle_one_connection (arg=0x128d890)
    at sql_connect.cc:1115
#7  0x00002b1f7b7e2f1a in start_thread () from /lib/libpthread.so.0
#8  0x00002b1f7bfa35d2 in clone () from /lib/libc.so.6
#9  0x0000000000000000 in ?? ()
(gdb) n
2149            trx = check_trx_exists(thd);
(gdb)
2153            longlong2str((ulint)savepoint, name, 36);
(gdb)
2155            error = (int) trx_release_savepoint_for_mysql(trx, name);
(gdb) p name
$17 = "BMHZC\000\000\0002\000\000\000\000\000\000\000\000�)\001\001", '\0' <repeats 11 times>, "\002\000\000\000\000\000\000\000��)\001\000\000\000\000\002\000\000\000\000\000\000\000\0225,\001\000\000\000"
(gdb) n
2157            DBUG_RETURN(convert_error_code_to_mysql(error, NULL));
(gdb) p error
$18 = 42 <<- This is DB_NO_SAVEPOINT which is correct
(gdb)

Regards,
-sunny

[11 Jan 2009 6:29] Sunny Bains

All,

This is a bug in InnoDB. InnoDB treats the savepoints like a stack, e.g.,

  SAVEPOINT a;
  SAVEPOINT b;
  SAVEPOINT c;
  SAVEPOINT b; <- Will delete c too

The savepoint state within InnoDB will end up looking like this:
  a
  b

The correct behavior is not to delete c and the state should look like this:
  a
  c
  b

Regards,
-sunny

[8 Apr 2009 19:46] Timothy Smith

Docs, everyone: I apologize, this bug was fixed previously, but the bug report was not updated properly.

This bug was fixed in 5.1.33, and 6.0.11 (not yet released).  The fix has not been backported to any 5.0 version.

Timothy

[8 Apr 2009 23:29] Paul DuBois

Noted in 5.1.33, 6.0.11 changelogs.

Setting a savepoint with the same name as an existing savepoint
incorrectly deleted any other savepoints that had been set in the
meantime. For example, setting savepoints named a, b, c, b resulted
in savepoints a, b, rather than the correct savepoints a, c, b.

[5 May 2010 15:24] Bugs System

Pushed into 5.1.47 (revid:[e-mail]-20100505145753-ivlt4hclbrjy8eye) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[6 May 2010 15:57] Paul DuBois

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

[28 May 2010 6:12] Bugs System

Pushed into mysql-next-mr (revid:[e-mail]-20100524190136-egaq7e8zgkwb9aqi) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (pib:16)

[28 May 2010 6:40] Bugs System

Pushed into 6.0.14-alpha (revid:[e-mail]-20100524190941-nuudpx60if25wsvx) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[28 May 2010 7:07] Bugs System

Pushed into 5.5.5-m3 (revid:[e-mail]-20100524185725-c8k5q7v60i5nix3t) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[29 May 2010 22:34] Paul DuBois

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

[15 Jun 2010 8:17] Bugs System

Pushed into 5.5.5-m3 (revid:[e-mail]-20100615080459-smuswd9ooeywcxuc) (version source revid:[e-mail]-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)

[15 Jun 2010 8:34] Bugs System

Pushed into mysql-next-mr (revid:[e-mail]-20100615080558-cw01bzdqr1bdmmec) (version source revid:[e-mail]-20100415070122-1nxji8ym4mao13ao) (pib:16)

[17 Jun 2010 12:17] Bugs System

Pushed into 5.1.47-ndb-7.0.16 (revid:[e-mail]-20100617114014-bva0dy24yyd67697) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[17 Jun 2010 13:04] Bugs System

Pushed into 5.1.47-ndb-6.2.19 (revid:[e-mail]-20100617115448-idrbic6gbki37h1c) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[17 Jun 2010 13:45] Bugs System

Pushed into 5.1.47-ndb-6.3.35 (revid:[e-mail]-20100617114611-61aqbb52j752y116) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)