Benchmark: Bypass magic to speed up the new entity field API

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.

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 :-/

This is at least major.

- (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.

@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.

Back to active, comments got in a while ago.

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

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).

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

Leaving as postponed, but adding "needs profiling" tag

.

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

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 ...

Re-titling for scope ...

Just unassigning issues that haven't been developed for a bit in the D8 queue.

Thank you for creating this issue to improve Drupal.

We are working to decide if this task is still relevant to a currently supported version of Drupal. There hasn't been any discussion here for over 8 years which suggests that this has either been implemented or is no longer relevant. Your thoughts on this will allow a decision to be made.

Since we need more information to move forward with this issue, the status is now Postponed (maintainer needs more info). If we don't receive additional information to help with the issue, it may be closed after three months.

Thanks!

Wanted to bump 1 more time.

#10 and #12 are still problems, but we have more recent issues open:

#3537863: Optimize field module's hook_entity_bundle_info() implementation
#3537962: EntityFieldManager::getFieldDefinitions() per-bundle caching can be expensive
#3542610: [12.x] Try to use property hooks to lazy instantiate entity keys.

I think between those it's safe to mark this as duplicate.

I don't think the __get() vs. ::get() calls themselves are a big issue, there are issues open around deprecating __get() elsewhere too I think but can't find them now.

Yes, I doubt the overhead of the magic methods is measurable. The reason I have long-term plans to deprecate them and improve the APIs is DX, having multiple ways to do the same thing can be confusing, especially if similar looking methods and properties are doing something very different (->entity and ->getEntity(), ->value and getValue() for example). One issue for that is #3281720: [meta] Deprecate __get/__set() on ContentEntityBase. I guess the closest thing would be a duplicate of that.

Entity and field definitions (even per-entity and per-bundle cache variations that we do have now, #10 is mostly outdated I think) can be very large and are a major contributor to overall memory usage of typical responses, but that's not related to magic methods.

ISTR back when we were developing pre-8.0, backend performance took a strong turn for the worse when magic methods replaced explicit calls. It may have been something else because many things were moving at the time, but still...

Magic methods were there from the very beginning of the entity field API, it was part of the BC layer that allowed us to introduce it. It is possible that you saw a regression compared to before, but that's all mixed up with the actual API, more complex data structures and so on.

It was also several PHP major versions ago.

Yes, if you do a raw comparison between $node->get('nid') and $node->nid, then $node->get('nid') is 1.5-2x as fast. But in absolute numbers, it's meaningless. Here's a simple test script:

use Drupal\node\Entity\Node;

$start = microtime(true);
$node = Node::load(1);
$end = microtime(true);
echo 'load: ' . round($end - $start, 10) . "\n";

$start = microtime(true);
$node->get('nid');
$end = microtime(true);
echo 'first call: ' . round($end - $start, 10) . "\n";

$start = microtime(true);
for ($i = 1; $i <= 100000; $i++) {
  $node->get('nid');
}
$end = microtime(true);

echo 'direct: ' . round($end - $start, 10) . "\n";

$start = microtime(true);
for ($i = 1; $i <= 100000; $i++) {
  $node->nid;
}
$end = microtime(true);

echo 'magic: ' . round($end - $start, 10) . "\n";

that gives me relatively stable numbers:

$ ddev drush scr local/entity_perf.php
load: 0.013048172
first call: 0.0224270821
direct: 0.0042119026
magic: 0.0069069862

The first direct call which needs to load the definitions and create the objects requires considerably more time than accessing an initialized field through __get() 100000x. And it gets even harder to compare on the field property level where magic has built-in optimizations that currently just do not exist when avoiding magic methods.

I'm not saying there aren't performance issues. it's obvious that accessing fields the first time is expensive. but magic methods aren't the issue here.

I'm also in favor of deprecating at least some magic methods per the refernced issue. But not for performance reasons.