Skip to content

Extra queries in logger #471

Closed
alexshelkov opened this Issue Jan 2, 2013 · 7 comments

4 participants

@alexshelkov

I have 2 entites:

Imr\Model\Order:
  collection: orders
  fields:
    id:
      id: true
  referenceOne:
    store:
      targetDocument: Imr\Model\Store
Imr\Model\Store:
  collection: stores
  repositoryClass: Imr\Model\Store\Repository
  fields:
    id:
      id: true
    token:
      type: string

When I try to exectue query:

$orders = $m->getRepository('Imr\Model\Order')->findBy(array());

foreach ($orders as $o) {
    if ($o->getStore())
        var_dump($o->getStore()->getToken());
    }
}

Why logger logs 5 quersies instead of 2 (mongodb profiler shows only 2 queries)? Here queres which logged:

array (size=5)
  'find' => boolean true
  'query' => 
    array (size=0)
      empty
  'fields' => 
    array (size=0)
      empty
  'db' => string 'zf2_modules' (length=11)
  'collection' => string 'orders' (length=6)

array (size=5)
  'find' => boolean true
  'query' => 
    array (size=1)
      '_id' => 
        object(MongoId)[270]
          public '$id' => string '50e460037664bc2902000010' (length=24)
  'fields' => 
    array (size=0)
      empty
  'db' => string 'zf2_modules' (length=11)
  'collection' => string 'stores' (length=6)

array (size=4)
  'limit' => boolean true
  'limitNum' => int 1
  'query' => 
    array (size=1)
      '_id' => 
        object(MongoId)[270]
          public '$id' => string '50e460037664bc2902000010' (length=24)
  'fields' => 
    array (size=0)
      empty

array (size=4)
  'limit' => boolean true
  'limitNum' => int 1
  'query' => 
    array (size=1)
      '_id' => 
        object(MongoId)[270]
          public '$id' => string '50e460037664bc2902000010' (length=24)
  'fields' => 
    array (size=0)
      empty

array (size=4)
  'limit' => boolean true
  'limitNum' => int 1
  'query' => 
    array (size=1)
      '_id' => 
        object(MongoId)[270]
          public '$id' => string '50e460037664bc2902000010' (length=24)
  'fields' => 
    array (size=0)
      empty

What 3 extra queries mean?

@jwage
Doctrine member
jwage commented Jan 16, 2013

The Store object is referenced so I believe that is each store being lazily loaded. You can preload all the stores in one query if you like using the referencing priming http://docs.doctrine-project.org/projects/doctrine-mongodb-odm/en/latest/reference/priming-references.html

@alexshelkov

@jwage this happens if only 1 order and 1 store is returned (if 2 orders and each have 1 store there are 9 queries). As you can notice $id in last 4 quieries are the same ('$id' => string '50e460037664bc2902000010'). Why Doctrie try to load same object 4 times, at least as it said in logger.

@alexshelkov alexshelkov reopened this Jan 16, 2013
@jwage
Doctrine member
jwage commented Jan 17, 2013

What version of the ODM are you using? Can you provide a test case that we can inspect?

@alexshelkov

Tested on version: 1.0.0-BETA7

Test code:

<?php
exec('rm -Rf cache');
exec('mkdir -p cache/doctrine/proxy cache/doctrine/hydrator');
exec('chmod -R a+w cache');

// Init composer autoloaders
$loader = require_once __DIR__ . '/../vendor/autoload.php';
require __DIR__ . '/TestDoctrine/_stubs/A.php';

use Doctrine\MongoDB\Connection;
use Doctrine\ODM\MongoDB\Configuration;
use Doctrine\ODM\MongoDB\DocumentManager;
use Doctrine\ODM\MongoDB\Mapping\Driver\AnnotationDriver;

AnnotationDriver::registerAnnotationClasses();

$config = new Configuration();
$config->setProxyDir(__DIR__ . '/../cache/doctrine/proxy');
$config->setProxyNamespace('Proxies');
$config->setHydratorDir(__DIR__ . '/../cache/doctrine/hydrator');
$config->setHydratorNamespace('Hydrators');
$config->setMetadataDriverImpl(AnnotationDriver::create(__DIR__ . '/TestDoctrine/_stubs'));
$config->setAutoGenerateHydratorClasses(true);
$config->setLoggerCallable(function (array $log) {
    var_dump($log);
});

$dm = DocumentManager::create(new Connection(null, array(), $config), $config);
$dm->getRepository('A')->findOneBy(array('id' => '50f7e0807664bc5766000000')); // document with ID may not exist

A class:

<?php
use Doctrine\ODM\MongoDB\Mapping\Annotations\Document;
use Doctrine\ODM\MongoDB\Mapping\Annotations\Id;

/** @Document */
class A
{
    /** @Id */
    protected $id;

    public function setId($id)
    {
        $this->id = $id;
    }

    public function getId()
    {
        return $this->id;
    }
}

Output:

array (size=5)
  'find' => boolean true
  'query' => 
    array (size=1)
      '_id' => 
        object(MongoId)[35]
          public '$id' => string '50f806428ead0ef32e000000' (length=24)
  'fields' => 
    array (size=0)
      empty
  'db' => string 'doctrine' (length=8)
  'collection' => string 'A' (length=1)
array (size=4)
  'limit' => boolean true
  'limitNum' => int 1
  'query' => 
    array (size=1)
      '_id' => 
        object(MongoId)[35]
          public '$id' => string '50f806428ead0ef32e000000' (length=24)
  'fields' => 
    array (size=0)
      empty
array (size=4)
  'limit' => boolean true
  'limitNum' => int 1
  'query' => 
    array (size=1)
      '_id' => 
        object(MongoId)[35]
          public '$id' => string '50f806428ead0ef32e000000' (length=24)
  'fields' => 
    array (size=0)
      empty
array (size=4)
  'limit' => boolean true
  'limitNum' => int 1
  'query' => 
    array (size=1)
      '_id' => 
        object(MongoId)[35]
          public '$id' => string '50f806428ead0ef32e000000' (length=24)
  'fields' => 
    array (size=0)
      empty

So even if the collection empty or 1 document exist 3 extra queries logged.

@romankonz romankonz referenced this issue in doctrine/DoctrineMongoODMModule Nov 21, 2014
Closed

improve ZendDeveloperToolbar integration #110

@romankonz

this is also happening when using the zf2 profiler.
(it's using the the odm logger)

$dm->createQueryBuilder(Message::class)->find()->limit(1) does report 0 queries
$dm->createQueryBuilder(Message::class)->find()->limit(1)->getQuery()also reports 0 queries.
but when calling $dm->createQueryBuilder(Message::class)->find()->limit(1)->getQuery()->execute();2 queries are reported.

@romankonz

I think this is because when logging is enabled, the loggableCursor logs this.

see https://github.com/doctrine/mongodb/blob/master/lib/Doctrine/MongoDB/LoggableCursor.php#L62

There's also an issue in doctrine/mongodb: doctrine/mongodb#151

@malarzm
Doctrine member
malarzm commented Jan 16, 2016

Closing as this duplicates #898

@malarzm malarzm closed this Jan 16, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.