Add query logging per Connection

+ $this->duration_execute = (microtime()-$start) * 1000;

Let's rename to duration and lets add the proper spacing.

Let's rename to duration ...

If we're going to store the query duration in a statement property, we should pre-define the property in the class definition so its access rules can be defined and so that it can be property documented. (See other properties in classes in the DB API.) I'd also prefer to make the property protected and add an accessor method of duration() to be consistent with the rest of the API.

(Right now everything is done via methods except for the lastQuery, which is an internal PDO property that is not well documented. I'm considering adding a method for that, too, for better documentation and consistency. Actually, that's not a bad way to handle the query debugging issue discussed on the dev list recently...)

Hm, something recently occurred to me here. Do we want to log per connection object, or per connection key? Per object would be easy, but then on a master/slave configuration we would have to poll each target individually to see what if any queries it had. Per key is probably what we want, and then the target used is another bit of info, but that gets somewhat more complex.

Moshe, thoughts?

OK, correction. It gets a LOT more complex. :-( I've got a decent approach in progress, though. Will report back later.

OK, here's a first cut at query logging. As I said, the need to log per connection key, not per connection, made it considerably more complicated. Specifically I've setup a new query logging class that gets referenced from each connection object. That logging class is then responsible for tracking and returning query information. I've put the logging class in its own file so that it will get lazy loaded, which means it doesn't get parsed if we're not logging anything. Yay, saving kittens!

Query information includes the query string, args, target, time, and the caller. The caller is not quite the raw record out of debug_backtrace(), because debug_backtrace() is highly stupid in its structure. It's all documented inline.

Of particular note is the concept of a logging key. The logging key lets us run multiple logs on a given connection simultaneously. Why do we want to do that? Because update_sql() is a hideous hack. The goal is that the devel module will have a "devel" log that it tracks, and then the update system can have its own "update" log that it toggles on and off for each update hook.

That way the database system reports back to us what queries ran rather than having to pass around a manual array of queries that we can't use prepared statements for. That means update_sql() goes away as does the $ret array that gets passed all around through Schema API. That greatly simplifies Schema API, and opens up the ability to have a much better set of API calls for it. That's all a follow-up patch, but that's what the multiple logging keys enables us to do.

I think this patch is all working, but I can't confirm it across multiple targets at the moment because we have no way to establish new targets from within a unit test. That is pat of #302300: Support adding and ignoring targets, which I am bumping to critical as it is now a blocker for this patch.

Still, go ahead and review now. :-)

About DatabaseLog::findCaller: we now have a _drupal_get_last_caller function in common.inc and a very similar backtracing logic that comes with the exception handler being implemented in #304924: Extend drupal_error_handler to manage exceptions. We should probably harmonize those.

* I agree with the harmonizing request made by Damien.

* It was (initially) not clear what a 'database target' is. I think the PHPdoc should made that more clear.

@Dries: "database target" is used all over the code already and is covered in the documentation. Unless I'm misusing the term here I don't think it's necessary to repeat it yet again.

From looking at the code, it looks like _drupal_get_last_caller() just works for the most recent call, not the filtered call that we need here to get out of the database system. A merge of the two would require adding some kind of filtering mechanism to _drupal_get_last_caller() that for now only the DB system will use. Any objection if I do so? What's that function used for, anyway? (I've never seen it before.) To be honest, though, I'm trying to keep the DB system as completely insular as possible without dependencies on the rest of Drupal.

I received this patch once more, incorporating the feedback and decided to go ahead and commit it.

Actually, Dries, this patch was not done. After the other patch went in I was able to finish writing unit tests and found all sorts of bugs in it that make it die horribly if you try adding a second connection or a second target. I was just in the process of trying to fix those when I CVS up'ed and got the old version of this patch, which completely broke my working copy. :-(

Not sure how you want to handle that, with a follow-up patch or a roll-back or what... I'm not doing anything else with it until I know what I'm doing.

Yes, this causes test failures in HEAD with that fatal error.

I hope I don't get in trouble for this, but I rolled this patch back because it caused SimpleTest to explode and die in a big way.

So, obviously, this still needs work. But at least the test suite passes again, so we don't hold up other patches. Hopefully Crell can resurrect some of the work he was doing the other night to fix the tests.

OK, I think I've got my working copy sorted out now. I'm attaching a not yet completed copy of the current patch against HEAD. This is more just a milestone for myself to refer back to so I have a working body of code.

This patch includes a lot of debugging code in it in various places, including dpm() so it depends on devel at the moment. That will, of course, be removed before the real patch is made but for right now it's necessary since simpletest is totally useless for debugging.

There is still one failing unit test I do not comprehend. The same (or nearly the same) code works fine in a custom page callback (temporarily stuck into database_test.module), but in a unit test the system is not reporting the target that was used properly. If anyone can figure out why before I do, it would be most appreciated. :-)

Found the problem! Word to the wise: Unit tests in the same class DO affect each other, so if you add a fake slave target in one unit test it will still be there for the next unit test that relies on there not being a slave target. *sigh* Attached patch should be fully functional across both multiple targets and multiple connections.

There is also a bug fix in here in the target fallback logic, in openConnection(). It now returns the target that was actually used, so that you can call that one now knowing that it is valid. None of the logging tests worked otherwise. I don't think it's worth splitting out to a separate patch, so I am calling it out here to minimize the kitten damage.

I am also considering refactoring the logging object to be one object per logging key per connection, rather than just one logger for all logging keys on a given connection. I'd originally made it a single object to avoid a loop in the statement object on each query... but just realized tonight that there's STILL a loop on every query, it's just in the logging object instead so there's no actual benefit there. That's just an internal refactoring, though, that should have no impact on the API, so I'm posting it as is to get the functionality available (so that devel.module can work again) as soon as possible. We can refactor the internals in a later patch.

I am also pushing this back up to critical because without this patch devel module's query logging can't work, and that does make development easier. :-)

I applied this patch to todays latest 7.x download. And it applied fine, and the log now appears in the bottom of the page.

I might be mistaken - but wasn't it supposed to show which database the query was sent to? Either I misconfigured (likely) the master-slave setup - or the plugin doesn't show which server the query ended up at..

I have the following in $databases

$databases = array (
  'default' => array (
    'default' => array (
      'driver' => 'mysql',
      'database' => 'drupal',
      'username' => 'web',
      'password' => '****',
      'host' => 'cluster-db1',
      'port' => '',
    ),
    'slave' => array (
      'driver' => 'mysql',
      'database' => 'drupal',
      'username' => 'web',
      'password' => '****',
      'host' => 'cluster-db2',
      'port' => '',
    ),
  ),
);

I am currently testing the master-slave setup - so if you have other tests you would like for me to run, just ask..
My setup currently consists of 3 virtual-machines (opensuse 11.0), two of them run mysql in a master-slave setup and the 3rd is running apache with php5.2.5.

-fangel

The API should be returning what target was used (not what was requested), and the unit tests won't pass if that's not the case. Whether or not devel is making use of that information at the moment I don't know. Moshe?

It would be awesome if devel could show if a given query hit the master (default) or slave.. Then you could use it to verify that the master-slave setup is working..

File an issue against devel for that one, but it has a +1 from me. :-) Does this patch look good to go otherwise?

I have zero Drupal-experience - but I do have lots of general PHP and PDO experience. With that being said - yes, I think the patch looks good.
It's a drawback that PDO doesn't allow one to see the queries with the inserted parameters - but this is no fault of the logger, more just a side effect of using prepared statements..

I will see if I can get the time to whip up a patch for Devel that will show the target of the queries - because I would love to get some Drupal experience, and why not help where a limited number of people can - that is, those that have master-slave setups..
I probably wont be till next week as I'm heading out for FOWA London tomorrow..

-fangel

Great! Please submit a patch to devel here: http://drupal.org/node/add/project-issue/devel

If you have questions or need help, feel free to poke Moshe or I in #Drupal. Having more people who can help test DB patches is a good thing. :-)

Looks like the patch needs a re-roll. No longer applies against HEAD.

Running these tests I get an exception:

Undefined index: lg_debug
Notice
database_test.test
1689
DatabaseLoggingTestCase->testEnableLogging()

I was not able to reproduce Moshe's results...? What page do you get that on, Moshe?

@33 - Follow up issue for the database_test_query_alter is now in #321161: Module implementation cache not flushed properly by Simpletest.

Committed to CVS HEAD. Thanks for the re-roll Moshe.

Looks like not all the files were committed.

That's probably a better status

Which are missing? There was only one new file.

Sorry for being ambiguous. Just log.inc was not committed.

Committed to CVS HEAD now. Sorry for the delay.