MySQL Bugs: #33531: falcon_debug_mask does not autoflush

Bug #33531	falcon_debug_mask does not autoflush
Submitted:	27 Dec 2007 8:06	Modified:	16 Mar 2008 11:20
Reporter:	Philip Stoev	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Falcon storage engine	Severity:	S3 (Non-critical)
Version:	6.0.4, 6.0.5-BK	OS:	Any
Assigned to:	Vladislav Vaintroub	CPU Architecture:	Any

Description:
Hello,

Setting falcon_debug_mask to a non-zero value results in debugging messages written to "standard output of mysqld" (as per the manual). However, it does not appear that this log is flushed all the way to disk, therefore on certain types of crashes, the last (probably most important) messages are lost.

I am setting this to S1 because that output may help me with bug #33518.

How to repeat:
1. set global falcon_debug_mask = 65535
2. commit a falcon transaction
3. Observe no output in mysql.err
4. shutdown mysqld
5. Output is there now - e.g. "Commit transaction 68"

Suggested fix:
Make all debug writes autoflush.

Immediately flushing debug messages will cause a terrible performance hit, so it should be configurable.

Maybe a separate bit on falcon_debug_mask can  be used for the purpose?

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

ChangeSet@1.2767, 2008-01-08 11:59:58+01:00, vvaintroub@vaio. +2 -0
  BUG#33531 - falcon_debug_mask does not autoflush.
  Introduced new variable falcon_debug_autoflush to force the fflush() 
  on the trace file after each debug message.
  Autoflush is on by default.

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

ChangeSet@1.2773, 2008-01-09 11:22:11+01:00, vvaintroub@vaio. +2 -0
  BUG#33531 - falcon_debug_mask does not autoflush.
  Introduced new parameter falcon_debug_autoflush to force fflush() to the
  trace file after each write.
  Autoflush is on by default.

Run some performance tests with and without fflush()ing.

As expected, fflush() does not cost that much.
The test "insert into t1 select * from t1;"
shows ~4% overhead added by fflush().

Autoflush : Query OK, 8388608 rows affected (1 min 32.88 sec)
No-Autoflush : Query OK, 8388608 rows affected (1 min 29.04 sec)

Clarification to my last comment-
the 4% overhead is not in general case, but only if much trace is written , i.e falcon_debug_mask is set to 8191 and on top of that storage/falcon/Dbb.cpp is modified such that DEBUG_KEYS is enabled.

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

ChangeSet@1.2775, 2008-01-09 20:24:38+01:00, vvaintroub@vaio. +2 -0
  Bug#33531 - Revert new parameter definition, always do fflush() when 
  writing trace

Patch is in mysql-6.0-release version 6.0.4

Pushed into 6.0.4-alpha

A note has been added to the 6.0.4 changelog: 

Using falcon_debug_mask to enable debugging messages could lead to some messages not being correctly flushed to the log file.