Bug #17674 Crashing mem leak after optimize (Assertion failure in file row0sel.c line 2840)
Submitted: 23 Feb 2006 17:21 Modified: 20 Nov 2011 8:34
Reporter: D O Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:4.1.7, 5.0 OS:Any (SunOS 5.9)
Assigned to: Assigned Account CPU Architecture:Any

[23 Feb 2006 17:21] D O
Description:
System seems to crash shortly after nightly optimization (on 1 table) finishes. We do see lots of processing waiting for the optimize to finish.  The optimization does complete however, then soon after (within a minute) it crashes.

From the error log:
=========================
060223  5:03:05InnoDB: Assertion failure in thread 2370 in file row0sel.c line 2840
InnoDB: Failing assertion: 0
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.
mysqld got signal 11;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8388600
read_buffer_size=131072
max_used_connections=14
max_connections=100
threads_connected=5
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 225791 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

-e 
Number of processes running now: 0
060223 05:03:07  mysqld restarted
060223  5:03:10  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
060223  5:03:11  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 211 2006060666.
InnoDB: Doing recovery: scanned up to log sequence number 211 2011303424
InnoDB: Doing recovery: scanned up to log sequence number 211 2016546304
InnoDB: Doing recovery: scanned up to log sequence number 211 2021789184
InnoDB: Doing recovery: scanned up to log sequence number 211 2027032064
InnoDB: Doing recovery: scanned up to log sequence number 211 2032274944
InnoDB: Doing recovery: scanned up to log sequence number 211 2037517824
InnoDB: Doing recovery: scanned up to log sequence number 211 2042760704
InnoDB: Doing recovery: scanned up to log sequence number 211 2048003584
InnoDB: Doing recovery: scanned up to log sequence number 211 2053246464
InnoDB: Doing recovery: scanned up to log sequence number 211 2058489344
InnoDB: Doing recovery: scanned up to log sequence number 211 2063732224
InnoDB: Doing recovery: scanned up to log sequence number 211 2068975104
InnoDB: Doing recovery: scanned up to log sequence number 211 2074217984
InnoDB: Doing recovery: scanned up to log sequence number 211 2079460864
InnoDB: Doing recovery: scanned up to log sequence number 211 2084703744
InnoDB: Doing recovery: scanned up to log sequence number 211 2089946624
InnoDB: Doing recovery: scanned up to log sequence number 211 2095189504
InnoDB: Doing recovery: scanned up to log sequence number 211 2100432384
InnoDB: Doing recovery: scanned up to log sequence number 211 2105675264
InnoDB: Doing recovery: scanned up to log sequence number 211 2110918144
InnoDB: Doing recovery: scanned up to log sequence number 211 2116161024
InnoDB: Doing recovery: scanned up to log sequence number 211 2121403904
InnoDB: Doing recovery: scanned up to log sequence number 211 2126646784
InnoDB: Doing recovery: scanned up to log sequence number 211 2131889664
InnoDB: Doing recovery: scanned up to log sequence number 211 2137132544
InnoDB: Doing recovery: scanned up to log sequence number 211 2142375424
InnoDB: Doing recovery: scanned up to log sequence number 211 2147618304
InnoDB: Doing recovery: scanned up to log sequence number 211 2151597599
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 0 182934528
060223  5:03:21  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Starting rollback of uncommitted transactions
InnoDB: Rolling back trx with id 0 182934121, 1 rows to undo
InnoDB: Rolling back of trx id 0 182934121 completed
InnoDB: Rollback of uncommitted transactions completed
060223  5:03:57  InnoDB: Flushing modified pages from the buffer pool...
060223  5:04:05  InnoDB: Started; log sequence number 211 2151597599
/usr/local/mysql/bin/mysqld: ready for connections.
Version: '4.1.7-standard'  socket: '/tmp/mysql.sock'  port: 3306  Official MySQL-standard binary

Output from optimize:
============================
 optimize        status  OK

How to repeat:
Not quite sure.  We have a process waiting to insert/update the table we are optimizing, and it keeps trying until the optimize finishes.  This table has many (about 700,000 each) inserts and updates through the day.  We do a big delete (about the same number) from the table right before the optimize.  This crash does not always happen (on the weekend, with less data, we have seen it stay up through the same operations).
[23 Feb 2006 22:38] Heikki Tuuri
Hi!

Your MySQL version is quite old. Does the problem persist if you upgrade to 4.1.18?

Regards,

Heikki
[16 Mar 2006 14:24] D O
This also happens in 5.0.

If the optimize is turned off, and the other processes continue, the db
does not crash. Also, note, there is plenty of memory and swap available
when it crashes.

Here is the output from the error log for 5.0:

060313  3:17:46  InnoDB: Error: cannot allocate 576 bytes of
InnoDB: memory with malloc! Total allocated memory
InnoDB: by InnoDB 3110199140 bytes. Operating system errno: 11
InnoDB: Check if you should increase the swap file or
InnoDB: ulimits of your operating system.
InnoDB: On FreeBSD check you have compiled the OS with
InnoDB: a big enough maximum process size.
InnoDB: Note that in most 32-bit computers the process
InnoDB: memory space is limited to 2 GB or 4 GB.
InnoDB: We keep retrying the allocation for 60 seconds...
060313  3:18:47  InnoDB: We now intentionally generate a seg fault so that
InnoDB: on Linux we get a stack trace.
mysqld got signal 11;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8388600
read_buffer_size=131072
max_used_connections=4
max_connections=100
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 225791 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

060313 03:18:50  mysqld restarted
[16 Mar 2006 14:26] D O
This is the 5.0 version information from the log:

InnoDB: Progress in percents: 1060313  3:20:46  InnoDB: Started; log sequence number 30 3593718320
060313  3:20:46 [Note] /mysqldata/mysql-standard-5.0.18-solaris10-i386/bin/mysqld: ready for connections.
Version: '5.0.18-standard'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Edition - Standard (GPL)
[16 Mar 2006 14:35] Heikki Tuuri
Hi!

InnoDB has allocated 3,110,199,140 bytes of memory. What is your my.cnf like?

What is your OS/hardware?

Regards,

Heikki
[16 Mar 2006 16:49] Heikki Tuuri
Ok, you have only 1.5 GB of buffer pool, but InnoDB says it has allocated 3 GB of memory!

Can you post several SHOW INNODB STATUS\G during the optimize, so that we would see why InnoDB has allocated 1.5 GB more memory?

Regards,

Heikki
[20 Mar 2006 20:53] Heikki Tuuri
Kevin,

you can also send files to heikki.tuuri@oracle.com

Regards,

Heikki
[21 Mar 2006 7:58] Marko Mäkelä
Fix memory leak in row_ins_duplicate_error_in_clust()

Attachment: bug17674.patch (text/x-patch), 607 bytes.

[21 Mar 2006 8:01] Marko Mäkelä
There is a memory leak in MySQL/InnoDB 5.0.3 and later that has nothing to do with the original bug reported for MySQL/InnoDB 4.1.7. I attached a patch to the "Files" section of this bug report. The memory leak should only manifest itself with tables having more than 90 columns.
[21 Mar 2006 8:15] Heikki Tuuri
I filed http://bugs.mysql.com/bug.php?id=18384 about the memory leak bug.
[29 Mar 2006 11:50] Heikki Tuuri
When 5.0.20 comes out, please test if the original problem of 4.1.7, the assertion failure, still happens.

It was probably the assertion below (ut_error) that failed. I have no idea what could cause that problem.

                trx->op_info = "fetching rows";

                if (prebuilt->n_rows_fetched == 0) {
                        prebuilt->fetch_direction = direction;
                }

                if (direction != prebuilt->fetch_direction) {
                        if (prebuilt->n_fetch_cached > 0) {
                                ut_error;
                                /* TODO: scrollable cursor: restore cursor to
                                the place of the latest returned row,
                                or better: prevent caching for a scroll
                                cursor! */
                        }
[29 Apr 2006 23:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".