MySQL Bugs: #39647: Warning about slow serial log writes should be prefixed with time stamp

Bug #39647	Warning about slow serial log writes should be prefixed with time stamp
Submitted:	25 Sep 2008 9:14	Modified:	26 May 2010 17:50
Reporter:	Olav Sandstå	Email Updates:
Status:	Unsupported	Impact on me:	None
Category:	MySQL Server: Falcon storage engine	Severity:	S3 (Non-critical)
Version:	6.0.7 - debug build	OS:	Any
Assigned to:	Lars-Erik BjÃ¸rk	CPU Architecture:	Any
Tags:	F_NEW FEATURE
Triage:	Triaged: D4 (Minor)

Description:
In a test where I inserts 10 GB of data into Falcon I see a long list of the following written to the MySQL .err file:

Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds
Serial log write took 2 seconds

To make these more useful they should be prefixed with a timestamp (and probably also "Falcon"). Without a timestamp it is hard to see if this was something that happened during a short period or randomly distributed over the about 20 hours it took to insert the data.

How to repeat:
Insert records of 100 byte into Falcon until you have inserted about 10 GB of data. If you will see these messages in your log or not is probably highly dependent on the performance of your disks.

Suggested fix:
Prefix these lines with something like:

[Falcon] 2008-09-25 11:09:32 Serial log write took 2 seconds

Verified using Falcon build from the mysql-6.0-falcon-team tree and configured with --with-debug

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

2859 lars-erik.bjork@sun.com	2008-10-07
      This is a fix for bug#39647 (Warning about slow serial log writes should be prefixed with time stamp)
      
      This fix prefixes time stamps on all messages sent through the interface provided by the Log class. StorageInterface::logger is registered as a receiver of the log, and 
      all messages received are prefixed before being printed. This ensures that other future/historic receivers of the log are not forced to have the Falcon specific time 
      stamp. The time stamps are on the format YYMMDD (h)h:mm:ss, to be in line with the time stamps printed by the server and by InnoDB.

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

2859 lars-erik.bjork@sun.com	2008-10-07
      This is a fix for bug#39647 (Warning about slow serial log writes should be prefixed with time stamp)
      
      This fix prefixes time stamps on all messages sent through the interface provided by the Log class. StorageInterface::logger is registered as a receiver of the log, and 
      all messages received are prefixed before being printed. This ensures that other future/historic receivers of the log are not forced to have the Falcon specific time 
      stamp. The time stamps are on the format YYMMDD (h)h:mm:ss, to be in line with the time stamps printed by the server and by InnoDB.
      
      Also added new Copyright notice (added ", 2008 Sun Microsystems, Inc.")

Patch reviewed and verifiedthat with the patch the output written to the error log now looks like this:

081007 03:31:12 Falcon: Serial log write took 2 seconds
081007 03:34:35 Falcon: Serial log write took 2 seconds
081007 03:36:16 Falcon: Serial log write took 2 seconds

Patch put back to 'in progress' because Falcon some places use the Logging system iteratively to build compound log messages. In this case, prefixing every part of a compound message will clutter the log.

We need a more specialized Logging mechanism to build compound messages than what exists in the Logging system today before prefixing with timestamps will be readable in every scenario.

A small example of such usage, taken from IndexPage::printPage(...) is:

<snip>

Log::debug("Supernodes:");
for (int i=0; i < SUPERNODES && page->superNodes[i]; i++)
	Log::debug("%d ",page->superNodes[i]);
Log::debug("\n");

<snip>

Setting this back to verified, as I am actually not currently working on this bug