The MySQL general log is one of my favorite features for a quick debug. I especially like the ability of starting and stopping it on demand, which was introduced in MySQL 5.1.
However, using the general log has its drawbacks.
Today I was debugging a nasty bug that results from two statements that should be applied sequentially, but that were instead concurrent. These kind of problems are hard to cope with, as they are intermittent. Sometimes all goes well, and you get the expected result. And then, sometimes the statements fly on different directions and I stare at the screen, trying to understand where did they stray.
After some try-and-fail, I decided to enable the general log just before the offending statements, and to turn it down immediately after. Guess what? With the general log on, the test never failed. What was an intermittently failing test became an always succeeding test.
What happened is that the general log delayed the query execution just enough for the following statement to arrive when it was expected.
In the end, the bug had to be unveiled using white box techniques.
Moral of the story: using a general log alters the status of the server. If you use it, be prepared to deal with its side effects.
Subscribe to:
Post Comments (Atom)
4 comments:
You can always try the MySQL 5.5 sqlstats plugin. See:
http://karlssonondatabases.blogspot.com/2010/11/more-on-sqlstats-sql-statement-monitor.html
This provides similar data to the general query log, but with "de-literalized" SQL statements and more.
/Karlsson
@Karlsson,
Thanks for the tip.
If I were dealing with MySQL 5.5 only, that would have been useful.
I am afraid, though, that whichever audit method I used would have delayed the query execution just enough to make the test succeed.
Yep, eternal problem of debugging a multi-threaded application.
The moment you decide to start dumping messages to standard output, is the moment you change the concurrency of your application, since standard output is serializing your threaded code.
It mostly succeeds, and sometimes fails your tests. I would assume with solutions such as writing to general_log the locks are held for longer time, which mean greater chance for obscuring your tests.
Hah! who would have thought that the general log is Schroedinger's cat?
Post a Comment