The InnoDB log graph is very flawed

[GoogleCodeExporter]

I don't know what wrong train of thought I had at the time, but the way the log 
graph is designed is completely wrong.  (See also issue 10).  Here's a 
conversation I had on IRC about this topic.

<Aurimas> Baron: unflushed log - does that have anything to do with 
checkpointing ?
<Aurimas> Baron: I must be missing something, I mean what is flushing here in 
the innodb log buffer context ?
<Baron> Aurimas, not exactly.  Checkpointing is more to do with flushing dirty 
pages.
<Aurimas> Baron: right, so where are these read from ?
<Baron> The logging system works like this.  Log entries are copied to the 
buffer, which is small.  Now and then, the buffer is locked and its contents 
are written to the log, starting at the current position.
<Baron> The log is much bigger than the buffer, of course.
<Baron> The system keeps track of the LSN at the time of the last fsync.
<Baron> This is the "log flushed to" stat in SHOW INNODB STATUS.
<Baron> The flushes can happen at each trx commit, or once a second or so if 
configured otherwise.
<Baron> I think this graph is actually very stupid.  I think I was insane when 
I made it.
<Baron> Let me check the source code.
<Baron> Yes, I am insane.
<Baron>       # TODO: I'm not sure what the deal is here; need to debug this.  
But the
<Baron>       # unflushed log bytes spikes a lot sometimes and it's impossible 
for it to
<Baron>       # be more than the log buffer.
<Baron>       debug("Unflushed log: $status[unflushed_log]");
<Baron>       $status['unflushed_log']
<Baron>          = max($status['unflushed_log'], 
$status['innodb_log_buffer_size']);
<Baron> My comment is completely wrong.  Vadim, would you agree that the log 
bytes unflushed has nothing to do with the log buffer size?
<Baron> Aurimas, the graph sample you showed me looks to me like the max() in 
the code above is taking effect, trimming the top off the "Unflushed Log" curve.
<Aurimas> Baron: I'm just thinking if log buffer is flushed every second or 
maybe even more often with tx_commit=1 does it even make sense to monitor log 
buffer activity ? I mean cacti updates every 300s or so
<Vadim> unflushed and log_buffer are different things
<Baron> Aurimas, it is an instantaneous thing, so yes it is going to be crazy 
different from one sample to the next, and probably does not have much meaning.
<Baron> I'll file a bug, the code and the graph need to be completely rethought 
:)
<Aurimas> Baron: I think it is also related to 
http://code.google.com/p/mysql-cacti-templates/issues/detail?id=10
<Baron> Aurimas, yes, but that issue turned out to be a wrong data type, as 
suggested in comment #3 in that issue

Original issue reported on code.google.com by baron.schwartz on 9 Jun 2010 at 11:44

Attachments:

• log_buffer.png