MySQL Bugs: #12263: MySQL server does not inform InnoDB which tables are opened for a cursor

Bug #12263	MySQL server does not inform InnoDB which tables are opened for a cursor
Submitted:	29 Jul 2005 7:58	Modified:	16 Sep 2010 5:53
Reporter:	Andrey Hristov	Email Updates:
Status:	Unsupported	Impact on me:	None
Category:	MySQL Server	Severity:	S4 (Feature request)
Version:	5.1	OS:	Linux (SLES 9)
Assigned to:	Konstantin Osipov	CPU Architecture:	Any
Tags:	cursor, innodb

Description:
The test case for this bug is the same as for 12243 but the test table contains only 1 row and not 2 rows.
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1091107168 (LWP 14028)]
0x0000000000732690 in trx_free (trx=0x2a970b98b8) at trx0trx.c:289
289             ut_a(trx->conc_state == TRX_NOT_STARTED);
(gdb) bt
#0  0x0000000000732690 in trx_free (trx=0x2a970b98b8) at trx0trx.c:289
#1  0x0000000000732c34 in trx_free_for_mysql (trx=0x2a970b98b8) at trx0trx.c:347
#2  0x000000000064d01d in innobase_close_connection (thd=0x3730fd0) at ha_innodb.cc:2143
#3  0x000000000063dfd2 in ha_close_connection (thd=0x3730fd0) at handler.cc:507
#4  0x00000000005511e9 in ~THD (this=0x3730fd0) at sql_class.cc:417
#5  0x0000000000563792 in end_thread (thd=0x3730fd0, put_in_cache=true) at mysqld.cc:1518
#6  0x0000000000579c40 in handle_one_connection (arg=0x3730fd0) at sql_parse.cc:1140
#7  0x0000002a95992919 in start_thread () from /lib64/tls/libpthread.so.0
#8  0x0000002a95eff8a3 in thread_start () from /lib64/tls/libc.so.6

How to repeat:
Use the attached test case.

See the table definition and the data in a comment in the source

Attachment: bug12263.c (text/x-csrc), 1.20 KiB.

I have problems compiling these cursor programs in hundin.mysql.fi, I get following error messages:

jan@hundin:~> gcc -c -I/usr/local/mysql/include/mysql bug12263.c
bug12263.c: In function `main':
bug12263.c:14: error: `MYSQL_STMT' undeclared (first use in this function)
bug12263.c:14: error: (Each undeclared identifier is reported only once
bug12263.c:14: error: for each function it appears in.)
bug12263.c:14: error: `prep_stmt' undeclared (first use in this function)
bug12263.c:14: error: `prep_stmt2' undeclared (first use in this function)
bug12263.c:16: error: `CURSOR_TYPE_READ_ONLY' undeclared (first use in this function)
bug12263.c:29: error: `STMT_ATTR_CURSOR_TYPE' undeclared (first use in this function)

Could someone help me to compile these so that I could see why there is crash.

Regards
    JanL

gcc -g -o bug12263 bug12263.c -I/home/andrey/mysql-5.0/include/ -lmysqlclient -lnsl -lz

Thank you for your bug report. However, I could not repeat his bug using 5.0.11bk with
following changeset http://lists.mysql.com/internals/27677.

jan@hundin:~> ./bug12263
jan@hundin:~>

Starting program: /home/jan/mysql-5.0/sql/mysqld
[New Thread 16384 (LWP 1672)]
[New Thread 32769 (LWP 1674)]
[New Thread 16386 (LWP 1675)]
[New Thread 32771 (LWP 1676)]
[New Thread 49156 (LWP 1677)]
[New Thread 65541 (LWP 1678)]
[New Thread 81926 (LWP 1679)]
[New Thread 98311 (LWP 1680)]
[New Thread 114696 (LWP 1681)]
[New Thread 131081 (LWP 1682)]
050729 12:44:25  InnoDB: Started; log sequence number 0 163719280
[New Thread 147466 (LWP 1683)]
050729 12:44:25 [Warning] mysql.user table is not updated to new password format; Disabling new password usage until mysql_fix_privilege_tables is run
050729 12:44:25 [Note] /home/jan/mysql-5.0/sql/mysqld: ready for connections.
Version: '5.0.11-beta-debug-log'  socket: '/home/jan/bugsocket'  port: 3306  Source distribution
[New Thread 163851 (LWP 1737)]
[New Thread 180236 (LWP 1804)]

Still reproducable here it very recent snapshot (2005 07 29 1057)

050729 13:02:48 [Note] /data/usr/local/src/mysql-5.0-200507291057/sql/mysqld: ready for connections.
Version: '5.0.11-beta-debug-log'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
[New Thread 1090910560 (LWP 11425)]
050729 13:02:52InnoDB: Assertion failure in thread 1090910560 in file trx0trx.c line 289
InnoDB: Failing assertion: trx->conc_state == TRX_NOT_STARTED
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/mysql/en/Forcing_recovery.html
InnoDB: about forcing recovery.

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1090910560 (LWP 11425)]
0x00000000006c7fa1 in trx_free (trx=0x2a970b70b8) at trx0trx.c:289
289             ut_a(trx->conc_state == TRX_NOT_STARTED);
Current language:  auto; currently c

Andrey,
I guess Jan is saying that the bug would be fixed by his earlier patch that is waiting for approval.

Hi!

I do not see how Jan's latest patch would fix this.

I guess the bug is that some cursor operation starts a transaction inside InnoDB, but that transaction is not registered with MySQL, and is not rolled back when the connection disconnects. A similar bug occurred with SHOW TABLE STATUS a month ago.

Maybe the best fix would be to change InnoDB to automatically run a rollback at a disconnect, regardless of whether MySQL calls a rollback or not. The downside is that some MySQL bugs may go unnoticed then.

Note that the code with 'InnoDB read views bound to cursors' is largely untested still. More bugs may be lurking.

Regards,

Heikki

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/internals/27848

Just pushed a patch. InnoDB still prints a warning to the .err log if we are closing a connection that has an active InnoDB transaction. We may remove that print in the future.

What should still be done is to determine how a cursor operation started an InnoDB transaction, and why MySQL did not commit or roll back it before closing the connection. I am reassigning this bug to Jan Lindström for further study.

Regards,

Heikki

The crash is now probably fixed in 5.0.11, but more study needed.
--Heikki

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/internals/27853

Tested today with 5.0.12 using gdb:

Version: '5.0.12-beta-debug-log'  socket: '/home/jan/bugsocket'  port: 3306  Source distribution
[New Thread 163851 (LWP 10311)]
[Switching to Thread 163851 (LWP 10311)]

Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x8c73800,
    thd=0x8c38358, lock_type=0) at ha_innodb.cc:6002
6002            row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
(gdb) c
Continuing.

Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x8c73800,
    thd=0x8c38358, lock_type=2) at ha_innodb.cc:6002
6002            row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
(gdb)
Continuing.

Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x8c73800,
    thd=0x8c38358, lock_type=0) at ha_innodb.cc:6002
6002            row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
(gdb)
Continuing.

Breakpoint 2, innobase_create_cursor_view() () at ha_innodb.cc:7163
7163            return(read_cursor_view_create_for_mysql(
(gdb)
Continuing.

Breakpoint 4, innobase_set_cursor_view(void*) (curview=0x40ad9068)
    at ha_innodb.cc:7192
7192            read_cursor_set_for_mysql(check_trx_exists(current_thd),
(gdb)
Continuing.

Breakpoint 4, innobase_set_cursor_view(void*) (curview=0x0)
    at ha_innodb.cc:7192
7192            read_cursor_set_for_mysql(check_trx_exists(current_thd),
(gdb)
Continuing.

Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x8c39780,
    thd=0x8c38358, lock_type=0) at ha_innodb.cc:6002
6002            row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
(gdb)
Continuing.

Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x8c39780,
    thd=0x8c38358, lock_type=2) at ha_innodb.cc:6002
6002            row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
(gdb)
Continuing.

Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x8c39780,
    thd=0x8c38358, lock_type=0) at ha_innodb.cc:6002
6002            row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
(gdb)
Continuing.

Breakpoint 3, innobase_close_cursor_view(void*) (curview=0x40ad9068)
    at ha_innodb.cc:7177
7177            read_cursor_view_close_for_mysql(check_trx_exists(current_thd),
(gdb)
Continuing.

Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x8c73800,
    thd=0x8c38358, lock_type=2) at ha_innodb.cc:6002
6002            row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
(gdb)
Continuing.

Breakpoint 5, innobase_commit (thd=0x8c38358, all=true) at ha_innodb.cc:1533
1533            DBUG_ENTER("innobase_commit");
(gdb)
Continuing.

Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x8c39780,
    thd=0x8c38358, lock_type=2) at ha_innodb.cc:6002
6002            row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt;
(gdb)
Continuing.
050808 12:24:01  InnoDB: Warning: MySQL is closing a connectionInnoDB: that has an active InnoDB transaction. We roll back that
InnoDB: transaction. 0 row modifications to roll back.

Thus, no crash anymore but still one active InnoDB transaction after client has closed the connection. This might be because a new transaction is created for a second fetch because the first transaction is already committed. Note also that there is no innobase_set_cursor_view() call before the second fetch. This bug might be related to a bug 12243.

Regards,
    Jan

Hi!

I do not understand several thinkgs in the gdb stepping.

MySQL calls ::external_lock() with lock_type 2, (I think that is F_WRLCK in fcntl.h). Why to use an X-locking read?

Why the program only opens one cursor 'read view'? Is it using the same read view for both cursors?

Do the table locks get correctly set and released in ::external_lock()?

Jan, are you sure that the program calls fetch without setting the cursor read view?

Does it call fetch AFTER closing the cursor read view?

Regards,

Heikki

Ok, I see.

	res= mysql_stmt_close(prep_stmt);	

Looks like the above closes the cursor read view.

	res= mysql_query(conn, "commit");

Then we have a commit.

        res= mysql_stmt_fetch(prep_stmt2);

But MySQL continues using cursor2 even though its read view has been closed!

I am assigning this bug to Konstantin. There are many things to test and fix.

Konstantin noted that trx->n_mysql_tables_in_use may be wrong if we let a cursor to live over a transaction commit. Then we cannot use it to decide if a current SELECT statement has ended. To fix this, MySQL should call a statement commit also after a SELECT. Then we could do without keeping that counter.

Regards,

Heikki

Hi!

After applying Konsta's patch (1. do not reset trx->read_view always back to the global read view in row0sel.c, 2. always register a stmt in ::external_lock(), regardless of trx->n_mysql_tables_in_use), the behavior in gdb looks correct, except that an active InnoDB transaction exists at the connection exit.

The reason for that active InnoDB transaction at the exit is that we usually set:

trx->active_trans = 1;

only in ::external_lock(), when we acquire a new table lock. A call of commit resets it to zero. But since in the test program we use the second cursor to fetch a row after the commit, that fetch operation starts a new InnoDB transaction without setting trx->active_trans=1!

Hmm... the semantics of active_trans and n_mysql_tables_in_use should be thinked over. An optimal solution would be to get rid of those variables altogether.

Currently, active_trans is only used to remove some unnecessary register function calls, and in signaling the prepared state of a transaction in XA.

n_mysql_tables_in_use  is used to make a commit when a SELECT statement ends in the autocommit=1 state.

Regards,

Heikki

Fixed by the patch for Bug#11832:

Subject: bk commit - 5.0 tree (konstantin:1.1975) BUG#11832                    

ChangeSet
  1.1975 05/08/10 18:36:13 konstantin@mysql.com +5 -0
  A fix and a test case for Bug#12243 "MySQL Server crashes with 2
  cursors (+ commit)" and Bug#11832 "Server crash with InnoDB + Cursors"
  See comments to the changed files.

http://lists.mysql.com/internals/28111

Approved by Heikki Tuuri via email.

The patch fixes most of the problems, but the n_mysql_tables_in_use can drift if a cursor is opened inside LOCK TABLES. Our work continues.

Fixed in 5.0 tree, tagged 5.1.12

Konsta,

did you also fix the case where a cursor is opened inside LOCK TABLEs?

Regards,

Heikki

Konstantin,

can you show the code that I can use to determine if a lock is taken for a cursor, or in a normal SELECT?

Regards,

Heikki

thd->cursor != 0

Changing the category and severity.

Currently all cursors are materialized. To be re-opened when we start working on sensitive cursors again.

Non-materialized cursor implementation is removed from MySQL 5.5 (WL#5502 Remove dead 5.0 class Sensitive_cursor).