MySQL Bugs: #39168: ERROR: the age of the last checkpoint ... exceeds the log group capacity

Bug #39168	ERROR: the age of the last checkpoint ... exceeds the log group capacity
Submitted:	1 Sep 2008 19:54	Modified:	14 Oct 2010 13:19
Reporter:	Louis Breda van	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	any	OS:	Any
Assigned to:	Inaam Rana	CPU Architecture:	Any
Tags:	log group capacity

Description:
Hello

As soon as I started using named-pipes (odbc option FLAG_FIELD_LENGTH + FLAG_FOUND_ROWS + FLAG_NAMED_PIPE)

I found following error in the errorlog 

080831 18:37:59  InnoDB: ERROR: the age of the last checkpoint is 167748105,
InnoDB: which exceeds the log group capacity 101917901.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
080831 18:38:15  InnoDB: ERROR: the age of the last checkpoint is 268792708,
InnoDB: which exceeds the log group capacity 101917901.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.

Can not be ^healty^. Assuming that this behavoir is not correct and that it can cause data corruption, I gave it severity critical, despite the fact that it seems to work as long as you do not need the recovery.  

Louis

How to repeat:
I had the problem under following conditions:
- msaccess vba manupulating large mysql-tables (few GByte) via ODBC
- enable-named-pipe
- innodb_log_buffer_size=8M
- innodb_log_file_size=54M
- innodb_flush_log_at_trx_commit=2
- max_allowed_packet=16M
- files in log group 2
- I do not use blobs, so record size are way below the log file size 

Also note that MySQL memmory usage was "fairly" big (perhaps nok)

Thank you for a problem report. Please, send your my.ini file content and the entire error log (compressed). I think this problem is NOT related to Connector/ODBC at all.

Louis, I am monitoring this report too but, so far, I agree with Valeriy.

Hello,

I will send you my ini file in a few moments, sending the error log is not possible because I cleared it.

Two point to consider:
- the error message I mailed was the only error message after the startup messages as far as I remember. The message was repeating every few minutes.
Startup message (including another long time error) below this mail
- I will send the ini file in a few moments. In that file I changed the
logfile setting from 54M to 128M. I did that *after* the error messages occured.
I did not yet retest. In fact I the original 54M should be more than engough I think.

Louis

080901 21:28:15 InnoDB: Started; log sequence number 319 105782284
080901 21:28:15 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_Z
080901 21:28:15 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
080901 21:28:15 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.26-rc-community' socket: '' port: 3306 MySQL Community Server (GPL)

Hello,

I just started a test trying to reproduce the problem.
No problem at all, even not with the bigger (54M => 128M) log file sizes.

Below the error log starting at the moment I changed the log file sizes.

However ..... it happens less frequent !

Louis

80901 21:09:53  InnoDB: Log file .\ib_logfile0 did not exist: new to be created
InnoDB: Setting log file .\ib_logfile0 size to 128 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
080901 21:09:55  InnoDB: Log file .\ib_logfile1 did not exist: new to be created
InnoDB: Setting log file .\ib_logfile1 size to 128 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
080901 21:09:57  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...
InnoDB: Last MySQL binlog file position 0 507041448, file name .\MAIN-bin.000028
080901 21:09:59  InnoDB: Started; log sequence number 319 105782284
080901 21:09:59 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_Z
080901 21:09:59 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
080901 21:09:59 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.26-rc-community'  socket: ''  port: 3306  MySQL Community Server (GPL)
080901 21:26:25 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: Normal shutdown

080901 21:26:28 [Warning] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: Forcing close of thread 4  user: 'root'

080901 21:26:28  InnoDB: Starting shutdown...
080901 21:26:30  InnoDB: Shutdown completed; log sequence number 319 105782284
080901 21:26:30 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: Shutdown complete

080901 21:28:15  InnoDB: Started; log sequence number 319 105782284
080901 21:28:15 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_Z
080901 21:28:15 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
080901 21:28:15 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.26-rc-community'  socket: ''  port: 3306  MySQL Community Server (GPL)
080902 18:50:47  InnoDB: Started; log sequence number 319 105782284
080902 18:50:47 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_Z
080902 18:50:47 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
080902 18:50:47 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.26-rc-community'  socket: ''  port: 3306  MySQL Community Server (GPL)
080902 19:32:57  InnoDB: ERROR: the age of the last checkpoint is 241588650,
InnoDB: which exceeds the log group capacity 241588224.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.

Please, try to repeat with a newer version, 5.1.28, and inform about the results.

Valeriy,

I allready noticed and installed the new release this afternoon.

And did a small test. No this problem is still there.

In order to make it easier to reproduce, I did set the logfilesize back to the original 54MB.

Below a part of the error log, beginning with the restart of the server, not fiding the errorlogs because I changed the errorlog file size in my.ini (from 128 back to 54), and deleted the old ones to make it work.

Note that I saw the problem on my XP32 bit machine as well.

Sincerely,

Louis
P.S. I also retested the 5.1 server <> ODBC 5.15 adapter. Just to see if 5.1.28 perhaps fixed that (probably an issue for odbc5.16). Whatever 5.1.28 <> 5.15 ODBC is still a NO GO (IMHO)

080914 19:09:18 InnoDB: Log file .\ib_logfile0 did not exist: new to be created
InnoDB: Setting log file .\ib_logfile0 size to 54 MB
InnoDB: Database physically writes the file full: wait...
080914 19:09:19 InnoDB: Log file .\ib_logfile1 did not exist: new to be created
InnoDB: Setting log file .\ib_logfile1 size to 54 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
080914 19:09:20 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...
InnoDB: Last MySQL binlog file position 0 507041448, file name .\MAIN-bin.000028
080914 19:09:22 InnoDB: Started; log sequence number 337 3730810380
080914 19:09:22 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_Z
080914 19:09:22 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
080914 19:09:22 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.28-rc-community' socket: '' port: 3306 MySQL Community Server (GPL)
080914 19:49:16 InnoDB: ERROR: the age of the last checkpoint is 101917918,
InnoDB: which exceeds the log group capacity 101917901.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
080914 19:49:32 InnoDB: ERROR: the age of the last checkpoint is 175719142,
InnoDB: which exceeds the log group capacity 101917901.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
080914 19:49:48 InnoDB: ERROR: the age of the last checkpoint is 244315541,
InnoDB: which exceeds the log group capacity 101917901.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
080914 19:50:04 InnoDB: ERROR: the age of the last checkpoint is 314433931,
InnoDB: which exceeds the log group capacity 101917901.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.

Just for info,

In order to speed up things I use transactions and batch updates here and there.
Because of that transactions can involve 600 rows.

But 600 lines are not nearly as big as 54 MByte !

What did come into my mind, but just thinking loud, are two things:
- transactions are related to a connection, I frequently have multiple mysql recordsets open via one connection
- during transactions, I might be stepping through recordsets not changing any thing at all, because the record is not a record out of the recordset to be changed or because the particular record does not need to be changed.
- If MySQL for some not understood reason, things that all those read and or skipped records might be changed and put them in the log ...... then 
1) it is terrible for the performance
2) it might .... perhaps .... explain things ..... ????

Note that if the transaction only include records terminated with an .update this idea "loud thinking" does not make any sence at all!!

Louis

I think I know when the problem happens, at least when I see it happenig.

Most of the time u update recordsets under control of VBA-code, but sometimes,
the update is so simple that I can perform the update with an update query.

And guess what, from my application loggings I see that most of the logsize errors occur during a "cn.Execute rsSetAddrStartDate" 

with other words, the connection / the server is updating a hole recordset outside my control :> !

And I asume now, that is sees the whole update mln-records as one big transaction ! And, not so strange, is fething all those mutations in the logfiles.

If this hypothesis is true, it would explain the error.
It just would raise another question:  "Why does it only happen, when using named pipes??"

Sincerely,

Louis

Please, check if you will ever have a problem like this with a newer version, 5.1.30.

Valeriy,

Long time ago that I had this problem, and no doubt about that. I made a work arround.

But I think I remember where I had that problem, so I can look into that code and see what happens If I remove the work arround for a moment. 
Of course that test will surely differ a bit form the past situation.

Perhaps friday or this weekend.

Louis

Hello Louis,
Do you have already the new test?. Thanks in advance.

Miguel,

I tried to reproduce the problem by creating an large update query.
No problem at all.

First I did run the update query from the MySQL query browser (5.16)
Then I performed the same query from MsAccess via ODBC5 (5.15)
(cn_tst.Execute sqlTest, MyRecAffected, where cursor is at the client side)

In both cases, I found error messages in the errorfile.
In fact just as expected (see below).

As written before, I think I understand the problem.
IMHO the whole update is seen as one big (too big) transaction.

Note that we are talking about recordsets / tables of a few milion records.

So, probalby the only solution is to segmentate te recordset to smaller pieces e.g. by using the Limit statement.

Sincerely,

Louis
PS. I did the check on a VISTA64 system running '5.1.31-community' (64 bit) having 8GB main memmory.

The errorlog shows:

090222 12:50:53 InnoDB: Started; log sequence number 30 1884474248
090222 12:50:53 [Note] Event Scheduler: Loaded 0 events
090222 12:50:53 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.31-community' socket: '' port: 3306 MySQL Community Server (GPL)
090222 19:29:53 InnoDB: ERROR: the age of the last checkpoint is 181188731,
InnoDB: which exceeds the log group capacity 181188404.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
090222 19:30:09 InnoDB: ERROR: the age of the last checkpoint is 224783929,
InnoDB: which exceeds the log group capacity 181188404.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
090222 19:33:49 InnoDB: ERROR: the age of the last checkpoint is 181188699,
InnoDB: which exceeds the log group capacity 181188404.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
090222 19:34:05 InnoDB: ERROR: the age of the last checkpoint is 223866030,
InnoDB: which exceeds the log group capacity 181188404.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.

Thank you for the feedback. Could you please provide the table(s) create statement, sequence of queries involved and the number of rows of the tables when the update command is performed?. Thanks in advance.

Miguel,

I did perform the test again with my actual DB-version using latest DB 5.1.32 

The query looks like this:

UPDATE (SELECT first_table.SomeKey, Min(first_table.StartKey) AS MinVanStartKey 
From first_table GROUP BY first_table.SomeKey ) Q1 
LEFT JOIN first_table ON Q1.SomeKey = first_table.SomeKey 
SET first_table.AddrStartDate = Q1.MinVanStartKey;

Where:
first_table: 
- SomeKey = varchar(35) and an index BTREE
- StartKey = bigint(20)
table Q1 is of course the result of a grouping on the same table

The table does have 37 fields varchar, tynyint,int bigint and datetime
(NO blogs or text etc !!!!!)

The table does have 7 indexes including the PK (being int(10)
The table does contain 1,7 mln rows

The error log looks like:  

090322 17:27:17  InnoDB: Started; log sequence number 63 4130822384
090322 17:27:17 [Note] Event Scheduler: Loaded 0 events
090322 17:27:17 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.32-community'  socket: ''  port: 3306  MySQL Community Server (GPL)
090322 17:38:20  InnoDB: ERROR: the age of the last checkpoint is 181188407,
InnoDB: which exceeds the log group capacity 181188404.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
090322 17:38:36  InnoDB: ERROR: the age of the last checkpoint is 224481078,
InnoDB: which exceeds the log group capacity 181188404.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.

I think I understand the problem, and from that I think that this is more
a limitation than a fault. So I lowerd the sevirity.

To by pass the problem I did some coding (half a year ago)

Hope this helps.

Sincerely,

Louis

From quick source code review I conclude that this error is just printed and program flow is not affected (looks data committed successfully).

So, it looks this is just warning and no data corruption is expected (at least if no other errors printed), but we need feedback from developers to conclude for sure. (And this is not ERROR: but WARNING: then).

Increasing log size usually eliminates such messages, but it is not always possible to increase log size 10 times bigger than largest BLOB (e.g. when BLOBs are >256M).

1) This error print is not dangerous if the age does not exceed the total log file size  'a lot'. InnoDB keeps a safety margin of 10 % of the total log file size.

2) If the age is 'a lot' too old, then a mysqld crash may cause InnoDB to be able to recover.

3) We still do not know what causes this bug.

Setting triage to R3 and E5.

InnoDB attempts to ensure that enough redo space is available before starting a DML operation. In case there is not enough space a checkpoint is performed in a synchronous fashion i.e.: all threads wait till the checkpoint is finished.

This space check and synchronous blocking is done via call to log_free_check(). There are some code paths (most notably update without secondary indexes) inside InnoDB where log_free_check() is not being called. This means that threads doing such update won't stop for a synchronous checkpoint and would keep on generating more redo. This can eventually result in InnoDB overwriting redo logs that are still needed in case of a crash.

See files row/row0*.c

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/111710

3110 Inaam Rana	2010-06-21
      Fixes bug#39168.
      Make a call to log_free_check() on all DML paths.

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/112079

3512 Inaam Rana	2010-06-24
      Add ChangeLog for bug#39168

The fix is committed into the InnoDB plugin in 5.1.49.

Pushed into 5.1.49 (revid:build@mysql.com-20100719143034-omcma40sblwmay3x) (version source revid:vasil.dimov@oracle.com-20100704071244-3lo4okzels3kvy1p) (merge vers: 5.1.49) (pib:16)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100723121820-jryu2fuw3pc53q9w) (version source revid:alik@sun.com-20100723121820-jryu2fuw3pc53q9w) (merge vers: 5.5.6-m3) (pib:18)

Pushed into mysql-next-mr (revid:alik@sun.com-20100723121929-90e9zemk3jkr2ocy) (version source revid:alik@sun.com-20100723121827-3bsh51m5sj6g4oma) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100622115215-kxtzx7xuugcxd375) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100622115215-kxtzx7xuugcxd375) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:marko.makela@oracle.com-20100622115215-kxtzx7xuugcxd375) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-next-mr (revid:alik@ibmvm-20100804081630-ntapn8bf9pko9vj3) (version source revid:marko.makela@oracle.com-20100622115215-kxtzx7xuugcxd375) (pib:20)

Adding to change log for 5.1, 5.5, 5.6:

The mechanism that checks if there is enough space for redo logs was
improved, reducing the chance of encountering this message: ERROR:
the age of the last checkpoint is x, which exceeds the log group
capacity y.

Pushed into mysql-5.1-telco-7.0 5.1.51-ndb-7.0.20 (revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (version source revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (merge vers: 5.1.51-ndb-7.0.20) (pib:21)

Pushed into mysql-5.1-telco-6.3 5.1.51-ndb-6.3.39 (revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (version source revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (merge vers: 5.1.51-ndb-6.3.39) (pib:21)

Pushed into mysql-5.1-telco-6.2 5.1.51-ndb-6.2.19 (revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (version source revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (merge vers: 5.1.51-ndb-6.2.19) (pib:21)

Already documented in the 5.1.49 changelog; no additional changelog entries required. Set back to Closed state.