Better query logging capabilities - implementation #153

Closed
wants to merge 6 commits into
from

Conversation

Projects
None yet
4 participants

First implementation for #151 - Better query logging capabilities

  • normal callback logging is still possible
  • added QueryLogger interface
  • added QueryLogger call in LoggableDatabase, LoggableCollection and LoggableCursor
  • added EchoQueryLogger and ChainLogger sample implementations

so 2 solution to the build problem on php 5.3

  1. set minimum php version to 5.4 - good for me and the rest of the world 😄
  2. i'll try to get this working on 5.3 tomorrow(tm)
- return parent::insert($a, $options);
+ return $this->logMethod($log, function () use (&$a, $options) {
+ return parent::insert($a, $options);
@jmikola

jmikola Feb 4, 2014

Owner

This appears to be one of the build failures for 5.3. Even on 5.4+, should a closure really be calling parent::?

@woodworker

woodworker Feb 5, 2014

i'll reworki it to be not a closure anymore

@jmikola

jmikola Feb 5, 2014

Owner

I'm more surprised that this was even supported and wondering if it has something to do with PHP 5.4 allowing $this to be bound on closures. Did you find documentation or prior code that was doing such a thing?

@woodworker

woodworker Feb 5, 2014

afaik since 5.4 closures are called in the context of the object/class so parent:: is nothing strange

see http://www.php.net/manual/en/closure.bind.php

anything more needed to merge this?

+ }
+ }
+
+ private function logAfter() {
@jwage

jwage Feb 8, 2014

Owner

Move the { to the next line.

+ *
+ * @author Martin Holzhauer <martin@holzhauer.eu>
+ */
+interface QueryLogger {
@jwage

jwage Feb 8, 2014

Owner

Move { to the next line.

+ public function stopQuery()
+ {
+ foreach($this->logger as $logger)
+ {
@jwage

jwage Feb 8, 2014

Owner

Move { to the line above at the end.

+ public function startQuery($parameter)
+ {
+ foreach($this->logger as $logger)
+ {
@jwage

jwage Feb 8, 2014

Owner

Move { to the line above at the end.

+ *
+ * @param QueryLogger $queryLogger
+ */
+ public function addLogger(QueryLogger $queryLogger){
@jwage

jwage Feb 8, 2014

Owner

Move { to the line below.

+ *
+ * @author Martin Holzhauer <martin@holzhauer.eu>
+ */
+class LoggerChain implements QueryLogger {
@jwage

jwage Feb 8, 2014

Owner

Move the { to the line below.

+ *
+ * @author Martin Holzhauer <martin@holzhauer.eu>
+ */
+class EchoQueryLogger implements QueryLogger {
@jwage

jwage Feb 8, 2014

Owner

Move { to the next line and remove the extra space.

+ echo PHP_EOL;
+ }
+
+ public function stopQuery()
@jwage

jwage Feb 8, 2014

Owner

What more do we have to do here?

@@ -65,7 +72,19 @@ public function log(array $log)
{
$log['db'] = $this->database->getName();
$log['collection'] = $this->getName();
- call_user_func_array($this->loggerCallable, array($log));
+ if($this->loggerCallable){
@jwage

jwage Feb 8, 2014

Owner

This should be if ($this->loggerCallable) {

+ call_user_func_array($this->loggerCallable, array($log));
+ }
+
+ if($this->queryLogger instanceof Logging\QueryLogger){
@jwage

jwage Feb 8, 2014

Owner

This should be if ($this->queryLogger instanceof Logging\QueryLogger) {

lib/Doctrine/MongoDB/LoggableCursor.php
+ call_user_func($this->loggerCallable, $data);
+ }
+
+ if($this->queryLogger instanceof Logging\QueryLogger){
@jwage

jwage Feb 8, 2014

Owner
if ($this->queryLogger instanceof Logging\QueryLogger) {
@@ -64,7 +71,19 @@ public function __construct(Connection $connection, \MongoDB $mongoDB, EventMana
public function log(array $log)
{
$log['db'] = $this->getName();
- call_user_func_array($this->loggerCallable, array($log));
+ if($this->loggerCallable){
@jwage

jwage Feb 8, 2014

Owner
if ($this->loggerCallable) {
+ call_user_func_array($this->loggerCallable, array($log));
+ }
+
+ if($this->queryLogger instanceof Logging\QueryLogger){
@jwage

jwage Feb 8, 2014

Owner
if ($this->queryLogger instanceof Logging\QueryLogger) {
+ }
+ }
+
+ private function logAfter() {
@jwage

jwage Feb 8, 2014

Owner

Move { to the next line.

+ }
+
+ private function logAfter() {
+ if($this->queryLogger instanceof Logging\QueryLogger){
@jwage

jwage Feb 8, 2014

Owner
if ($this->queryLogger instanceof Logging\QueryLogger) {
Owner

jmikola commented Feb 8, 2014

I'm out for the weekend but hope to review this early in the coming week.

anything new?

igorw commented Feb 19, 2014

Bump.

Owner

jmikola commented Feb 19, 2014

I will review this within 8 hours, after I leave the office tonight.

- if ( ! is_callable($loggerCallable)) {
- throw new \InvalidArgumentException('$loggerCallable must be a valid callback');
+ if ( ! is_callable($loggerCallable) && !($queryLogger instanceof Logging\QueryLogger)) {
+ throw new \InvalidArgumentException('$loggerCallable must be a valid callback or $queryLogger must be an instance of Doctrine\MongoDB\Logging\QueryLogger');
@jmikola

jmikola Feb 20, 2014

Owner

You're already type-hinting $queryLogger, so does it matter if it's null?

@jmikola

jmikola Feb 20, 2014

Owner

Ah, just saw the testNoLoggerGivenThrowsException() test below. Since you've changed the log() method to conditionally invoke $this->loggerCallable or the QueryLogger, I wonder if this constructor exception even matters anymore. If the class has neither a callable or QueryLogger set, we do nothing. On its own, the library shouldn't even construct the class based on Connection::doSelectDatabase().

- if ( ! is_callable($loggerCallable)) {
- throw new \InvalidArgumentException('$loggerCallable must be a valid callback');
+ if ( ! is_callable($loggerCallable) && !($queryLogger instanceof Logging\QueryLogger)) {
+ throw new \InvalidArgumentException('$loggerCallable must be a valid callback or $queryLogger must be an instance of Doctrine\MongoDB\Logging\QueryLogger');
@jmikola

jmikola Feb 20, 2014

Owner

Same comment as https://github.com/doctrine/mongodb/pull/153/files#r9897431. I think we can just remove this.

@@ -59,6 +59,26 @@ public function setLoggerCallable($loggerCallable)
}
+ /**
+ * Set QueryLogger
+ *
+ * @param Logging\QueryLogger $queryLogger
@jmikola

jmikola Feb 20, 2014

Owner

Can you add a use statement for the QueryLogger class? That makes it easier to see at a glance what the file is using.

@@ -45,13 +50,15 @@ class LoggableCollection extends Collection implements Loggable
* @param EventManager $evm EventManager instance
* @param integer $numRetries Number of times to retry queries
* @param callable $loggerCallable The logger callable
+ * @param Logging\QueryLogger $queryLogger The QueryLogger object
@jmikola

jmikola Feb 20, 2014

Owner

Same comment as earlier regarding a use statement for Logging\QueryLogger. That would also shorten this to QueryLogger and avoid the alignment issue.

+ public function startQuery($parameter)
+ {
+ foreach($this->logger as $logger)
+ {
@jmikola

jmikola Feb 20, 2014

Owner

foreach gets { on the same line.

+ */
+interface QueryLogger
+{
+ public function startQuery($parameter);
@jmikola

jmikola Feb 20, 2014

Owner

I think the comments from https://github.com/doctrine/dbal/blob/master/lib/Doctrine/DBAL/Logging/SQLLogger.php would be valuable here. For instance, it let's users know that stopQuery() can be used for timing.

+ *
+ * @author Martin Holzhauer <martin@holzhauer.eu>
+ */
+interface QueryLogger
@jmikola

jmikola Feb 20, 2014

Owner

Since the DBAL class is SQLLogger, I'm wondering if this should be MongoLogger or BSONLogger for the name of the protocol or syntax we're logging. The name "query" seems very generic.

Owner

jmikola commented Feb 20, 2014

@woodworker: Do you have an example of how stopQuery() is used for timing? I didn't find anything in DBAL for that, but I'm curious if the QueryLogger would be responsible for nesting state and timers each time startQuery() is called, and unwrapping on each stopQuery().

*/
- public function __construct(Database $database, \MongoCollection $mongoCollection, EventManager $evm, $numRetries, $loggerCallable)
+ public function __construct(Database $database, \MongoCollection $mongoCollection, EventManager $evm, $numRetries, $loggerCallable = null, Logging\QueryLogger $queryLogger = null)
@jmikola

jmikola Feb 20, 2014

Owner

@jwage: I'm worried about adding more constructor arguments here, since it's a change that then has to be implemented whenever we extend the class (to ensure we accept the argument with the same default value, and then pass it along to the parent). Assuming we allow both $loggerCallable and the QueryLogger to be optional (as I suggest here)., what do you think about having setter methods for each? We'd naturally leave the $loggerCallable argument in place with a null default value for BC.

@jwage

jwage Feb 20, 2014

Owner

Makes sense to me. 👍

@woodworker

woodworker Feb 21, 2014

i'll move it to a setter

but best solution would be to remove everything starting at $numRetries and just inject the configuration object so future config params will not be injected seperate

@jmikola

jmikola Feb 24, 2014

Owner

Agreed. This is something I've thought about for a while. I changed the constructor order of some of these core classes for 1.1.0 via 39a2b7c, so perhaps we can consider this for 1.2.0? Otherwise, it'd be something for 2.0 if we acknowledge it's a BC break. I didn't before, as I assumed most users access these classes through the Connection, so that was the public API to preserve. Thoughts, @jwage?

@jmikola
nested querylogger is in PHP not needed - because singlethreaded
start timer in startQuery method and then stop that timer in stopQuery
nothing will happen in between

and it's realy simple just a microtime(true) in startQuery adn a microtime(true) in stopQuery and then log to statsd or whatever

Owner

jmikola commented Feb 24, 2014

@woodworker: I was thinking it's quite possible that a higher level method (e.g. something in GridFS, which doesn't yet have logging -- todo in #37) might call underlying collection methods. That higher level method might start/stop on its own, but internally the collection methods would log as well.

@jmikola jmikola added this to the 1.2.0 milestone Mar 27, 2014

Owner

jmikola commented Feb 24, 2015

@woodworker: After our discussion last month in Berlin, can this be closed? I recall you said that the driver's stream context logging proved more useful to you.

@jmikola jmikola added the feature label Feb 24, 2015

Owner

jmikola commented Jun 22, 2015

Closing, but feel free to re-open if you'd like to revisit this.

@jmikola jmikola closed this Jun 22, 2015

@jmikola jmikola removed this from the 1.2.0 milestone Jun 22, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment