I figured out it's possible to write to $this->$name without issuing a __set() call from inside __set(). This allows for a "magic-magic-static-cache". I've run some quick benchmark:

With my branch:

17009.16ms for 1000000 runs.
0.01700916ms per run

With the attached patch applied:

12672.81ms for 1000000 runs.
0.01267281ms per run

So the property access improve from 17µs to 12,67µs on my machine. I'd have expected the difference to be bigger though. :/

Benchmarked code:

$iterations = 1000000;
timer_start('test');
for ($i = 0; $i < $iterations; $i++) {
    $entity->user_id->value = 1;
}
timer_stop('test');
echo timer_read('test')."ms for $iterations runs. \n";
echo (timer_read('test') / $iterations) ."ms per run";
Files: 
CommentFileSizeAuthor
d8_property_magic_performance.patch1.48 KBfago

Comments

I figured out that the magic magic cache only applies to the first level in my quick-patch, so the not cached lower level influence my results. Re-run it just with the first level:

With patch:

373.03ms for 1000000 runs.
0.00037303ms per run

Without patch.

4003.14ms for 1000000 runs.
0.00400314ms per run

So that's an improvement, more than 10x times faster. :)

$entity = entity_create('entity_test', array());
$iterations = 1000000;
timer_start('test');
for ($i = 0; $i < $iterations; $i++) {
   $var = $entity->user_id;
}
timer_stop('test');
echo timer_read('test')."ms for $iterations runs. \n";
echo (timer_read('test') / $iterations) ."ms per run";

http://vdev.local/drupal-8/node/3?page=3&q=node/3

With having the latest patch from #1778178: Convert comments to the new Entity Field API applied I ran "ab -c1 -n100" on page http://vdev.local/drupal-8/node/3?page=3 (showing 50 comments).

So here is a comparison of the impact of the overall page request:

With the patch applied (branch property-comment)

Concurrency Level:      1
Time taken for tests:   41.443 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      13065600 bytes
HTML transferred:       13009500 bytes
Requests per second:    2.41 [#/sec] (mean)
Time per request:       414.431 [ms] (mean)
Time per request:       414.431 [ms] (mean, across all concurrent requests)
Transfer rate:          307.88 [Kbytes/sec] received
Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:   401  414  13.2    410     496
Waiting:      398  410  12.4    407     493
Total:        401  414  13.2    410     496
Percentage of the requests served within a certain time (ms)
  50%    410
  66%    414
  75%    418
  80%    422
  90%    432
  95%    438
  98%    446
  99%    496
100%    496 (longest request)

and here without the patch (regular 8.x brach)

Concurrency Level:      1
Time taken for tests:   40.923 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      13065600 bytes
HTML transferred:       13009500 bytes
Requests per second:    2.44 [#/sec] (mean)
Time per request:       409.234 [ms] (mean)
Time per request:       409.234 [ms] (mean, across all concurrent requests)
Transfer rate:          311.79 [Kbytes/sec] received
Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.2      0       1
Processing:   396  409  14.0    406     508
Waiting:      393  406  14.0    403     504
Total:        396  409  13.9    406     508
Percentage of the requests served within a certain time (ms)
  50%    406
  66%    410
  75%    415
  80%    418
  90%    422
  95%    430
  98%    444
  99%    508
100%    508 (longest request)

So the version without the changes appears to a bit faster, however differences are below the standard derivation. Running it multiple times gave similar results though.

However, it should be noted that the current implement of comment rendering is everything else than efficient as it disables and enables the entity property API compatibilityMode multiple times (each time a field api attacher is called) per rendering a comment, whereas enable the mode means copying around property values...

Here are my manual tests with Devel output.

The numbers are the average of 20 page requests on each setup on two separate sites, installed on the same local virtual server. All tests are done as user ID 1.

Ubuntu 12.04
PHP 5.3.10
MySQL 5.5.4

Comment patch, without any comments

Page execution time was 126.63 ms. Memory used at: devel_boot()=1.44 MB, devel_shutdown()=7.56 MB, PHP peak=7.75 MB.

D8 core, without any comments

Page execution time was 121.64 ms. Memory used at: devel_boot()=1.44 MB, devel_shutdown()=7.03 MB, PHP peak=7.25 MB.

Comment patch, with 50 comments

Page execution time was 636.86 ms. Memory used at: devel_boot()=1.44 MB, devel_shutdown()=12.83 MB, PHP peak=14 MB.

D8 core, with 50 comments

Page execution time was 323.79 ms. Memory used at: devel_boot()=1.44 MB, devel_shutdown()=8.41 MB, PHP peak=9.5 MB.

Same setup with ab -c1 -n100 as anonymous user. Page cache turned off.

Comment patch, with 50 comments

Server Software:        Apache
Server Hostname:        001.dev
Server Port:            80
Document Path:          /node/100
Document Length:        5778 bytes
Concurrency Level:      1
Time taken for tests:   8.637 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Non-2xx responses:      100
Total transferred:      629700 bytes
HTML transferred:       577800 bytes
Requests per second:    11.58 [#/sec] (mean)
Time per request:       86.369 [ms] (mean)
Time per request:       86.369 [ms] (mean, across all concurrent requests)
Transfer rate:          71.20 [Kbytes/sec] received
Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.2      0       2
Processing:    73   86  16.1     83     188
Waiting:       69   82  15.6     80     184
Total:         73   86  16.1     84     188
Percentage of the requests served within a certain time (ms)
  50%     84
  66%     89
  75%     91
  80%     92
  90%     96
  95%    102
  98%    172
  99%    188
100%    188 (longest request)

D8 core, with 50 comments

Server Software:        Apache
Server Hostname:        002.dev
Server Port:            80
Document Path:          /node/100
Document Length:        5778 bytes
Concurrency Level:      1
Time taken for tests:   8.370 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Non-2xx responses:      100
Total transferred:      629700 bytes
HTML transferred:       577800 bytes
Requests per second:    11.95 [#/sec] (mean)
Time per request:       83.695 [ms] (mean)
Time per request:       83.695 [ms] (mean, across all concurrent requests)
Transfer rate:          73.47 [Kbytes/sec] received
Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:    69   83  17.2     80     228
Waiting:       66   79  16.7     76     218
Total:         69   84  17.3     80     228
Percentage of the requests served within a certain time (ms)
  50%     80
  66%     84
  75%     88
  80%     90
  90%     97
  95%    106
  98%    113
  99%    228
100%    228 (longest request)

Same setup with ab -c1 -n100 -C SESS...=... as user ID 1.

Comment patch, 50 comments

Server Software:        Apache
Server Hostname:        001.dev
Server Port:            80
Document Path:          /node/100
Document Length:        118068 bytes
Concurrency Level:      1
Time taken for tests:   67.273 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      11861000 bytes
HTML transferred:       11806800 bytes
Requests per second:    1.49 [#/sec] (mean)
Time per request:       672.729 [ms] (mean)
Time per request:       672.729 [ms] (mean, across all concurrent requests)
Transfer rate:          172.18 [Kbytes/sec] received
Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       0
Processing:   617  673  31.3    670     784
Waiting:      604  659  31.1    656     770
Total:        617  673  31.3    670     784
Percentage of the requests served within a certain time (ms)
  50%    670
  66%    683
  75%    689
  80%    700
  90%    717
  95%    730
  98%    746
  99%    784
100%    784 (longest request)

D8 core, with 50 comments

Server Software:        Apache
Server Hostname:        002.dev
Server Port:            80
Document Path:          /node/100
Document Length:        117180 bytes
Concurrency Level:      1
Time taken for tests:   34.175 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      11772200 bytes
HTML transferred:       11718000 bytes
Requests per second:    2.93 [#/sec] (mean)
Time per request:       341.753 [ms] (mean)
Time per request:       341.753 [ms] (mean, across all concurrent requests)
Transfer rate:          336.39 [Kbytes/sec] received
Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:   292  342  32.5    339     475
Waiting:      285  334  31.7    331     467
Total:        292  342  32.5    339     476
Percentage of the requests served within a certain time (ms)
  50%    339
  66%    349
  75%    358
  80%    364
  90%    383
  95%    397
  98%    445
  99%    476
100%    476 (longest request)

It'd be good to see some profiling output from xhprof in terms of function calls etc., I don't think ab or devel is going to be useful here.

Title:Speed up consequent calls to bypass magicSpeed up the new entity field API
Status:Needs review» Needs work

I guess this should be moved to the core queue now.

Issue tags:+Entity Field API

adding tag

Project:D8 Entity API improvements» Drupal core
Version:» 8.x-dev
Component:Entity Property API» entity system

One unfortunate thing is that the "New Field API" basically destroys the efforts that went into #1040790: _field_info_collate_fields() memory usage, since the new field_entity_field_info() (called from DataBaseStorageController::getFieldDefinitions()) calls field_info_instances(), which loads all instances in memory.

The plan in D8 is to deprecate field_info_fields() / field_info_instances() (the "give me all" variant, only keep field_info_instances($entity_type, $bundle)), because they are performance killers. They are still here after #1040790: _field_info_collate_fields() memory usage went in because the goal there was to keep an easy D7 backport.
You should only access instances within a given $entity_type and $bundle - that, we can keep reasonably performant.
Meaning, we shouldn't allow getFieldDefinitions($constrants), but only getFieldDefinitions($entity_type, $bundle).

For the cases where you do need to have an overview of all existing fields and instances, we now have a much lighter field_info_field_map(), which seems to somewhat duplicate DatabaseStorageController::$entityFieldInfo.

In short, this and #1040790: _field_info_collate_fields() memory usage were worked on in parallel and ignorant of each other, and landed about the same time. They will need to be merged somehow, but I'm not familiar enough with the new API to have a clear notion of how. Also, I'm afk for the next month or so :-/

Priority:Normal» Major
Issue tags:+Performance

This is at least major.

One unfortunate thing is that the "New Field API" basically destroys the efforts that went into #1040790: _field_info_collate_fields() memory usage, since the new field_entity_field_info() (called from DataBaseStorageController::getFieldDefinitions()) calls field_info_instances(), which loads all instances in memory.

Well, this runs per entity-type, so it's not that bad.

Meaning, we shouldn't allow getFieldDefinitions($constrants), but only getFieldDefinitions($entity_type, $bundle).

Makes sense. If the bundle is ommitted, just the base-fields of an entity should be returned.

For the cases where you do need to have an overview of all existing fields and instances, we now have a much lighter field_info_field_map(), which seems to somewhat duplicate DatabaseStorageController::$entityFieldInfo.

Looks like it follows the same idea, yep. Once we only have entity base fields and configured fields, the hook is mostly unnecessary - except for dynamic fields. I guess we have to look into optimizing this again then, depending on how it turns out to be exactly in the end. Maybe the cache could be moved to the upper level (= on the entity field api level) then and make configurable fields use it as well.

- (yched) One unfortunate thing is that the "New Field API" basically destroys the efforts that went into #1040790: _field_info_collate_fields() memory usage, since the new field_entity_field_info() (called from DataBaseStorageController::getFieldDefinitions()) calls field_info_instances(), which loads all instances in memory.

- (fago) Well, this runs per entity-type, so it's not that bad.

No, it is a problem. field_info_instances($entity_type) is as expensive as field_info_instances(). It's only field_info_instances($entity_type, $bundle) that got optimized.

Assigned:Unassigned» chx

@chx: Note that #1778178: Convert comments to the new Entity Field API contains a large amount of changes related to performance, so you probably want to check the patch there and possibly help to finalize that so that we can finally convert an actual entity type to NG and start working on the others. I'd suggest to postpone this issue on that one and re-evaluate after it went in.

Status:Needs work» Postponed

Status:Postponed» Active

Back to active, comments got in a while ago.

Assigned:chx» Unassigned

Let's not wait on me :) if I get to it I will re-assign.

Title:Speed up the new entity field APIBypass magic to speed up the new entity field API

Problem with writing a field object to a public $entity->field property is that someone could replace it with a new $field object, what could lead to quite some breakage. So given this doesn't present a big boost, I don't think we should do this.

I agree with at least holding off on this until it can be shown to have a big boost. I think there are some situations where it will, especially if also applied at the item level (->value).

Status:Active» Postponed

Seems like it should be postponed or won't fix.

Leaving as postponed, but adding "needs profiling" tag

Issue tags:+Performance

.

Two months later. Should we unpostpone this? Close it?

Status:Postponed» Active

I think we should re-profile this to see what impact this has - if any. Also the benchmark of #0 might be misleading (if and I don't know that) debug() code was left in ...

Title:Bypass magic to speed up the new entity field API Benchmark: Bypass magic to speed up the new entity field API
Assigned:Unassigned» Fabianx

Re-titling for scope ...

Issue summary:View changes
Issue tags:+Needs benchmarks