[redis cache] mysterious millions of class metadata queries

[flaushi]

Bug Report

My setup:
I am using redis as cache provider (metadata and query cache) in my symfony 4 application.
I have rewritten the doctrine DBAL datetime type to automatically hydrate Carbon instances.

By chance, I looked into redis-cli and inspected the MONITOR command which prints each executed command on the redis server. So I found this output:

1579646630.737155 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.737466 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.740321 [10 127.0.0.1:54310] "MGET" "egaSpV8Dyt:%5B47b0072c16018cab57f09e5a8e71c27e%5D%5B1%5D"
1579646630.740634 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.740945 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.743785 [10 127.0.0.1:54310] "MGET" "egaSpV8Dyt:%5B47b0072c16018cab57f09e5a8e71c27e%5D%5B1%5D"
1579646630.744097 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.744404 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.747869 [10 127.0.0.1:54310] "MGET" "egaSpV8Dyt:%5B47b0072c16018cab57f09e5a8e71c27e%5D%5B1%5D"
1579646630.748181 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.748492 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.751324 [10 127.0.0.1:54310] "MGET" "egaSpV8Dyt:%5B47b0072c16018cab57f09e5a8e71c27e%5D%5B1%5D"
1579646630.751616 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.751897 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.754732 [10 127.0.0.1:54310] "MGET" "egaSpV8Dyt:%5B47b0072c16018cab57f09e5a8e71c27e%5D%5B1%5D"
1579646630.755044 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.755357 [10 127.0.0.1:54310] "MGET" "0Db4hBLOK5:%5BCarbon%5CCarbon%24CLASSMETADATA%5D%5B1%5D"
1579646630.758280 [10 127.0.0.1:54310] "MGET" "egaSpV8Dyt:%5B47b0072c16018cab57f09e5a8e71c27e%5D%5B1%5D"

This shows that the app is querying class meta data for Carbon instances over and over.
I assume these queries must have a performance impact.

Even worse, this behaviour does not only occur once per request, I found this during one console command, so doctrine seems to query the class metadata for each fetched object.

Q	A
BC Break	no
Version	v2.10.0

Summary

The DBAL issues many cache queries for Carbon class metadata. They are so frequent that it gives a performance impact.

How to reproduce

My entities are annotated in a standard fashion, e.g.:

/**
 * DataSample
 * 
 * @ORM\Table(indexes={ @ORM\Index(name="reference_date", columns={"refdate"}) })
 * @ORM\Entity(readOnly=true)
 */
class DataSample
{
    /**
     * @var Carbon
     * @ORM\Column(name="refdate", type="datetime")
     */
    public $referenceDate;
}

Here is my symfony config and the custom Carbon type:

doctrine:
    dbal:
        types:
            uuid:  Ramsey\Uuid\Doctrine\UuidType
            datetime: App\DBAL\Types\CarbonMicrosecondsType
    orm:
        auto_generate_proxy_classes: false
        auto_mapping: true
        metadata_cache_driver:
            type: service
            id: doctrine.metadata_cache_provider
        query_cache_driver:
            type: service
            id: doctrine.query_cache_provider
services:
    doctrine.query_cache_provider:
        class: Symfony\Component\Cache\DoctrineProvider
        public: false
        arguments:
            - '@doctrine.query_cache_pool'

    doctrine.metadata_cache_provider:
        class: Symfony\Component\Cache\DoctrineProvider
        public: false
        arguments:
            - '@doctrine.metadata_cache_pool'
framework:
    cache:
        default_redis_provider: 'redis://%env(REDIS_HOST)%/%env(REDIS_DB)%'
        pools:
            doctrine.query_cache_pool:
                adapter: cache.adapter.redis
                default_lifetime: 0
            doctrine.metadata_cache_pool:
                adapter: cache.adapter.redis
                default_lifetime: 0

Here is the custom type:

class CarbonMicrosecondsType extends Type
{
    const TYPENAME = 'datetime';

    public function getSQLDeclaration(array $fieldDeclaration, AbstractPlatform $platform)
    {
        if (isset($fieldDeclaration['version']) && $fieldDeclaration['version'] == true) {
            return 'TIMESTAMP';
        }
        if($platform instanceof PostgreSqlPlatform)
            return 'TIMESTAMP(6) WITHOUT TIME ZONE';
        else
            return 'DATETIME(6)';
    }

    public function convertToPHPValue($value, AbstractPlatform $platform)
    {
        if($value === null || $value instanceof CarbonInterface)
            return $value;

        $val = static::dbToPHPValue($value);
        if ( ! $val) {
            throw ConversionException::conversionFailedFormat(
                $value,
                $this->getName(),
                'Y-m-d H:i:s.u'
            );
        }

        return $val;
    }

    public const formatString = 'Y-m-d H:i:s.u';

    public static function dbToPHPValue($value) : Carbon
    {
        if ($value instanceof DateTimeInterface) {
            return Carbon::instance($value);
        }
        $val = DateTime::createFromFormat(self::formatString, $value);

        if ( ! $val) {
            $val = Carbon::instance(date_create($value));
        } else {
            $val = Carbon::instance($val);
        }
        return $val;
    }

    public function convertToDatabaseValue($value, AbstractPlatform $platform)
    {
        if (null === $value) {
            return $value;
        }

        if ($value instanceof DateTimeInterface) {
            return $value->format(self::formatString);
        }

        throw ConversionException::conversionFailedInvalidType(
            $value,
            $this->getName(),
            ['null', 'DateTime']
        );
    }

    public function getName()
    {
        return self::TYPENAME;
    }
    public function requiresSQLCommentHint(AbstractPlatform $platform)
    {
        return true;
    }
}

Expected behaviour

The queries should not happen in that frequency

[bastnic]

@flaushi hi, which version of Symfony 4 do you use?

[flaushi]

Hi, I am using 4.3.9
I cannot tell if this a behavior that has been there already for a longer time. I never inspected redis monitor in that way.

[Ocramius]

Potentially related to something like ->setParameter('foo', $date), where $date is a Carbon instance? Try specifying the type of parameter, because I think this is related to doctrine/orm#7528

[flaushi]

So, should I use datetime as parameter type value then?
I guess the class name Carbon is what gives the problem.
@Ocramius mentioned this probelem here
Or should I specify \DateTime, or \DateTime::class?
so my choices are

$q = $em->createQuery('SELECT d from App\Entity\DataSample d WHERE d.referenceDate = :date');
$q->setParameter('date', Carbon::now(), 'datetime');
// or
$q->setParameter('date', Carbon::now(), \DateTime::class);

[Ocramius]

I think it needs to be a reference to this:

dbal/lib/Doctrine/DBAL/Types/DateTimeType.php

Line 20 in c2b8e6e

return Types::DATETIME_MUTABLE;

[flaushi]

...which is datetime right?

[flaushi]

If I understood your comment in the other issue correctly, the problem is not about Carbon, it also affects original DateTime instances? 😳
For strings and scalars, this works.
Wouldn't it make sense to have one explicit check for DateTime as well? Nobody expects this behavior, and binding datetimes to queries is a pretty common scenario.

[Ocramius]

It affects any object, since the ORM will first check if that object is a mapped type, hence the query to the metadata. It will fall back to DBAL types if no mapping is found, and it will use the DBAL type directly when provided

[flaushi]

Ok, thanks. I annotated all setParameter calls that bind a DateTime with datetime as third parameter now and the cache queries have gone away. From that point of view the issue can be closed. Do you think this unexpected behaviour should be mentioned in the docs somewhere?

[Ocramius]

Not sure: it's designed to work that way, since the ORM is trying to type-guess what was given, and first checking if it is an entity from which we need to extract metadata.

What could be done, is making a map of types to be excluded from metadata lookup (in the metadata factory)

[flaushi]

So you mean a pre-population of AbstractClassMetadataFactory::loadedMetadata?
I am not familiar with the library in depth. Which types apart of DateTime (and derived classes) would be suitable for such a short cut?

[Ocramius]

More like a "miss" list, together with a "hit" list.

Whenever metadata is not found in the metadata driver, a second lookup should fail immediately.

[flaushi]

Sounds like caching the metadata cache results to me...

I think for datetime the lookup can just be omitted completely. Same as for scalars...

BTW at which point in the code are scalars handled differently? Exactly this position should also be the forking point for datetime...

[Ocramius]

DateTime does not have special handling in ORM, and shouldn't either: it is an object like any other, and nothing prevents it from being mapped as an entity on its own

[flaushi]

I understand your view. I think this might turn into a philosophical discussion about whether or not one should handle very frequent special cases explicitly.
I am not in the position to start this discussion here. See it just as a proposal.

Yes, DateTime is an object, but no, it's no entity, since for DBAL it is always converted into a string representation and then given to the DB.

BTW: Could I just use $q->setParameter('created_at', $datetime->format('Y-m-d'));?

[Ocramius]

That would work, but then you lose the advantage of conversion.

All you're required to do to bypass metadata lookups is to provide the type of the parameter (third argument). Otherwise, the ORM will just try its best effort at finding a fitting type.

[flaushi]

Yes, absolutely, I already added the third parameter everywhere.

I was just saying that the need for this third parameter (just for the DateTime case and to prevent the lookup) is counterintuitive.

[github-actions]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.