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 11:14	Modified:	25 Mar 21:11
Reporter:	Olav Sandstaa
Status:	Verified
Category:	Server: Falcon	Severity:	S3 (Non-critical)
Version:	6.0.7 - debug build	OS:	Any
Assigned to:	Lars-Erik Bjørk	Target Version:
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