Upgrade from 1.x to 2.x has broken code with models magic getters/setters

[trogwarz]

Prerequisites

• Ubuntu 12.04.x/14.x
• PHP 5.5.x/5.6.x (from ppa:ondrej/php and from deprecated ppa:ondrej/php5-5.6 too)
• Transformers from thephpleague/fractal package
• Each API response contains mostly 100 objects + 3 connected objects (total 400 minus duplicates)
• XhProf as profiler

Phalcon 1.3.x (tested mostly on 1.3.6)

API response less than 1 second, about 5-7 megabytes RAM. XhProf shows that slowest point is \file_exists in composer autoload. Cool, fast.

Phalcon 2.x (tested mostly on 2.0.10)

Strange happens. API response 40-60 seconds, very huge RAM eating (1 gigabyte and more plus swap), 100% eats one CPU core.

XhProf shows that bottleneck is \ReflectionClass::getProperty and traces leading to \Phalcon\Mvc\Model\Resultset\Simple::current. After some digging into, i found that PR #11417 made my code totally broken. Callgraph attached at the end of this post.

Workaround

As a workaround i can extend magic setter of model in my base model and copy-paste some code from sources like this:

public function __set($property, $value)
{
    if (is_array($value) || is_object($value))
        return parent::__set($property, $value);

    if ($this->_possibleSetter($property, $value))
        return $value();

    $this->{$property} = $value;

    return $value();
}

But, i think, this is a crooked nail. In my company and projects, we use only setters/getters for models and repos and don't care about setting like $model->someprop = 'foobar' (thus, it's not affects toArray call behaviour).

Questions

1. Why it uses very slow Reflection instead of getModelsMetadata (that can be cached!)?
2. Really need caching of metadata here that got from Reflection. Can it be done? I can make PR for this but i have no experience with Zephir and time for this will be very huge (only in first part of august, maybe).
3. Can i update Phalcon later to LTS version and be sure that it (workaround, i mean) won't broke anything?

Thanks for any suggestions.

Callgraph

[andresgutierrez]

Maybe we should create an optimizer called is_private in Zephir, so the ORM does not have to use Reflection

[Jurigag]

Wait, 8 total calls and 21 seconds spend on this ? What a hell. how this is possible ?

Can someone post code for reproduce for this ? Im not sure if this is an issue, beacause one call for ReflectionClass:getProperty in php user land is like 5E-5

Or you mean is it done on this 400 resultset like 20 seconds ?

Can you post this table and code to reproduce problem ? I just checked it on some 400 random results, selected them using Model::find() setting values directly on resultset is done in like 1.2E-5 sec. While foreaching each row from resultset and set some property it's done in 0.0007 sec. Did you tried to disable xhprof/xdebug ?

@trogwarz

[trogwarz]

@Jurigag , \ReflectionClass is really slow for any high-speed solution but Phalcon has great metadata's that can be cached. XhProf result shows that.

Simple test: install Phalcon 1.3.6, send request to api – get response in <1s, upgrade Phalcon to 2.x, send same request – get response in >20s. No other changes, 100% repeatable (on multiple versions in my subject post). Request will look like (in my concrete project) api.example.com/v1/drivers?with=(cars,docs,passengers) and respond will have 100 users (with 10+ properties) plus 300 connected objects except duplicates.

I can trim my project (and make it as small as possible to reproduce issue) to post it in public for debugging and testing that later patch really solves issue. But remember – i use Phalcon with thephpleague/fractal (that i don't reversed yet but i decide that Fractal uses syntax like $model->property a lot) and – it will take long time because i will not be available the next two weeks on the internet. So, i'll post sample project about 2-7 august, really sorry for that.

ps: xDebug was disabled in all tests (and don't even installed). XhProf doesn't make any overhead by-design.

[Jurigag]

But as i wrote you. I checked it on 400 records setting:

Resultset->property was done in 1.2E-5 sec
Foreach each row in resultset and set property directly on model like this:
$model->property was done in 0.0007 sec

I don't have slow execeution. Just that's why we need some script te reproduce, beacause i can't maybe andres can't.

[trogwarz]

@Jurigag , it's not enough to just "get some models from repository". You need to:

1. Create many (at least four in my example) models and implement Fractal Transformer in project for them.
2. Set up "one-to-many" relation from one of created models to all others
3. Implement Fractal TransformerManager in project and use it for working with responses
4. Link these models in Transformer as "optional available includes"
5. Request about 100 objects with all configured optional includes

As i said, i don't know right now how exactly it works inside, especially with combination of magic setters (and don't have enough time and computer near me until 2-7 august). But simple test with upgrading Phalcon to version with mentioned PR – breaks this code. Workaround in my post – solves issue.

I think that \ReflectionClass in _isVisible method is bottleneck now – that's the point why i'm creating issue here, in Phalcon project. If anybody can explain that it's slows down because of Fractal or my code smells bad or by any other reason – cool, i'll create issue there or refactor my code with "best practices" (-:

Example part from \Acme\Controllers\Driver:

$models      = \Acme\Models\Driver::find(['limit' => 100]);
$transformer = new \Acme\Transformers\Driver();
$collection  = new \League\Fractal\Resource\Collection($models, $transformer->setPartials([]), 'Driver');
$transformerManager->parseIncludes(['cars', 'docs', 'passengers']);
return $transformerManager->createData($collection);

Example part of \Acme\Transformers\Driver:

public function includeCars(\Acme\Model\Driver $driver)       { return $this->collection($driver->getCars()      , new \Acme\Transformers\Driver   , 'Driver'   ); }
public function includeDocs(\Acme\Model\Driver $driver)       { return $this->collection($driver->getDocs()      , new \Acme\Transformers\Doc      , 'Doc'      ); }
public function includePassengers(\Acme\Model\Driver $driver) { return $this->collection($driver->getPassengers(), new \Acme\Transformers\Passenger, 'Passenger'); }

[Jurigag]

Relations doesn't have anything here beacause you don't join them. They will be there if you will access them(additional queries) As I wrote I already checked _isVisible it doesn't bottleneck for me, we just need whole script to reproduce it.

Well i was writeng this on mobile, i see you probably access them ? Some code example is really needed right now. I don't have ReflectionClass bottleneck in _isVisible :) Both on php 5.6.x and 7.

It's no point for andres for adding something to zephir if we are not sure for 100% use case. As you see above i have super small times of executing just on setting some random property which is executing all those phalcon internal method you have and don't have ANY bottlenecks.

Those transformers don't havy anything to do here. As you see it's internally ReflectionClass::getProperty in _isVisible which is really simple method. Whatever you do there shouldn't do anything fancy. You could just try do:

$models      = \Acme\Models\Driver::find(['limit' => 100]);
$models->someProperty = "someValue"

And according to your enviroment you should have some slowliness too.

[sergeyklay]

@trogwarz Could you please check the 3.0.x branch now?

[sergeyklay]

@trogwarz Waiting for you

[andresgutierrez]

As ReflectionClass was removed I think this is fixed, also declare properties on every model must speed up any application.

[trogwarz]

Results of testing (ubuntu 12.04, 14.04) with different versions of php-fpm and phalcon:

[
    {
        "v-php-fpm" : "5.6.23-1+deprecated+dontuse+deb.sury.org~precise+1",
        "v-phalcon" : "1.3.6",
        "time-php"  : 0.0746169090271,
        "time-db"   : 0.026349306106567
    },
    {
        "v-php-fpm" : "5.6.23-1+deprecated+dontuse+deb.sury.org~precise+1",
        "v-phalcon" : "2.0.13",
        "time-php"  : 26.32877898216248,
        "time-db"   : 0.079745054244995
    },
    {
        "v-php-fpm" : "5.6.23-1+deprecated+dontuse+deb.sury.org~precise+1",
        "v-phalcon" : "2.1.0 RC 1",
        "time-php"  : 28.077505111694336,
        "time-db"   : 0.02750825881958
    },
    {
        "v-php-fpm" : "5.6.23-1+deprecated+dontuse+deb.sury.org~precise+1",
        "v-phalcon" : "3.0.0",
        "time-php"  : 26.12922596931458,
        "time-db"   : 0.032534837722778
    },
    {
        "v-php-fpm" : "5.6.24-1+deb.sury.org~precise+1",
        "v-phalcon" : "1.3.6",
        "time-php"  : 0.36090803146362,
        "time-db"   : 0.30925035476685
    },
    {
        "v-php-fpm" : "5.6.24-1+deb.sury.org~precise+1",
        "v-phalcon" : "2.0.13",
        "time-php"  : 26.84207701683,
        "time-db"   : 0.1939103603363
    },
    {
        "v-php-fpm" : "5.6.24-1+deb.sury.org~precise+1",
        "v-phalcon" : "2.1.0 RC 1",
        "time-php"  : 27.166598796844,
        "time-db"   : 0.10126161575317
    },
    {
        "v-php-fpm" : "5.6.24-1+deb.sury.org~precise+1",
        "v-phalcon" : "3.0.0",
        "time-php"  : 26.581640958786,
        "time-db"   : 0.023773193359375
    }
]

• v-php-fpm: phpversion()
• v-phalcon : \Phalcon\Version::get()
• time-db : \Phalcon\Db\Profiler\Item::getTotalElapsedSeconds
• time-php : microtime(true) between start in index.php and Phalcon\Mvc\Micro::after

Preparing XhProf dumps, right now, and trimming my app to give you example of code. Just wait for a bit – i'm after fulltime work now.

[andresgutierrez]

@trogwarz Can you please compile using 3.0.x branch, fix hasn't landed into master yet

[trogwarz]

@andresgutierrez, am i doing it right?

git clone git://github.com/phalcon/cphalcon.git /tmp/cphalcon
cd /tmp/cphalcon/build
git checkout 3.0.x
./install
service php5.6-fpm restart
php -r "echo Phalcon\Version::get();"

[sergeyklay]

@trogwarz For dev branches use this aproach:

...
git checkout 3.0.x
zephir fullclean && zephir build  # use latest zephir here
...

[trogwarz]

@sergeyklay , oops, didn't know. Tested with build like you said on ubuntu 12.04/14.04 and php5.6/php7.0 – cool! Now works fast, yay! Thank you!