_field_info_collate_fields() resource usage

Pretty sure field tests will fail, if not lots of other things, but CNR for the bot anyway.

It doesn't really sneak it in, that was point #1 ;) Although unless there's a hook running on those definitions, I don't see any reason to do all that processing and looping on potentially hundreds of fields unless we absolutely have to. The two fails suggest it might well be fine to cache the prepared array.

However (and I though I hadn't even posted this) the patch doesn't actually reduce memory usage by half, it looks about the same in my testing. I want to check with devel generate and memory profiling before/after though to see if it affects that situation, which is where the bug was found - will do that a bit later today. Although even if it doesn't actually reduce memory, I don't see any reason to duplicate all that data given it's easy enough to retrieve it in the consumer functions.

edit: wait a minute, better data coming soon.

When you have a lot of fields and instances, _field_info_collate_fields() really starts to add up, I have it at anywhere between 15-30% of page execution time on node/n depending on the page.

Original patch didn't apply so I've attached just one with the caching for now, and before/after webgrind screenshots - this isn't on a clean install, but it's a handy one which has a lot of fields and instances.

CNR just for the bot.

Patch was made with bzr, here's one from cvs in case that helps.

@barry, yes I noticed that but it's completely consistent - 250 calls with the patch applied, 16 without, haven't figured out why yet though. Also 200+ calls which just return from static cache frankly isn't a lot.

I can't do anything with "potential nasty side effects" that are "tricky to predict" - that basically means issues that we don't know exist, but might possibly crop up at some point in the future. If you have a more concrete example of what those are, perhaps something that appeared before, then great, if not I'm prepared to take that risk for 20% (or even 5%) of page execution time. It's a small patch, easy to roll back if such a race condition gets found without an easy fix otherwise.

Here's some better webgrind data (if you can call posting a screenshot either 'better' or 'data', yay for yched's new dev environment). _field_info_prepare_instance() is the worst offender.

Now, you will not see this on a clean HEAD install with an empty db, because that has about 5 or less field instances, not 295. If you think 295 field instances is crazy, you may well be right, but if 295 leads to 20% of page execution time, then 100 (10 bundles with 10 instances each, quite reasonable, and only going to go up as more things become both fieldable and fields), may well be 6-7%, 6-7% on just about every page request is still a lot.

We could try to get better data - i.e. have a script generate 25, 50, 100, 200, 500 instances, then profile and benchmark before/after with each. If it is indeed a linear slowdown (and that seems likely), then I'd be tempted to mark this critical.

And the reason I'm focusing on this rather than the initial memory problem is that I'm not convinced my original patch fixed the memory issue, and because I care about CPU more.

OK now profiling on a clean HEAD install with xhprof.

I used the following to create fields and instances on the node/article bundle, then profiled user/1 at 50, 100, 200 and 400 fields + instances. There is overhead from displaying a node with lots of fields attached, even if they're not rendered, so profiling user/1 allows us to better isolate the cost of _field_info_collate_fields() by itself against a normal request (although I think there's still some other overhead, but the profiling results are sane enough to not worry too much). Numbers are a couple off because I didn't bother to delete core fields/instances before running this, but we're talking at most 2%.

Screenshots of the _field_info_collate_fields() detail for 50/100/200/400 fields+instances, then 400 with the patch applied all attached.

Once you get to 50 fields + instances (which is very easy to do), it's already taking up 20% of both page execution time and memory, which is enough for me to bump this to critical - Drupal.org has 40 'fields' just on user profiles.

At 400 fields+instances, which I hope never to see in the wild but wouldn't be impossible on some kind of ecommerce or library database, we're looking at 47% inclusive CPU and memory usage, moving the caching reduces the CPU to 10% and memory to 20% (probably more of a gain with something like memcache which doesn't need to unserialize the array).

// $Id$
/**
 * Creates dummy fields and instances.
 */

/**
 * Bulk generate fields and instances for a bundle.

 * @param $quantity
 *   Integer, defaults to 50.
 * @param $entity_type
 *   The entity type, defaults to node.
 * @param $bundle
 *   The bundle, defaults to article.
 */
function fields_generate($quantity = 50, $entity_type = 'node', $bundle = 'article') {
  for ($i = 1; $i <= $quantity; $i++) {
    $field = array(
      'field_name' => 'a' . strtolower(_fields_random_name()),
      'type' => 'text',
    );
    field_create_field($field);
    $instance = array(
      'field_name' => $field['field_name'],
      'label' => $field['field_name'],
      'entity_type' => $entity_type,
      'bundle' => $bundle,
    );
    field_create_instance($instance);
  }
}


/**
 * SimpleTest ripoff.
 */
function _fields_random_name($length = 8) {
  $values = array_merge(range(65, 90), range(97, 122), range(48, 57));
  $max = count($values) - 1;
  $str = chr(mt_rand(97, 122));
  for ($i = 1; $i < $length; $i++) {
    $str .= chr($values[mt_rand(0, $max)]);
  }
  return $str;
}

That overview's great yched.

I think new view modes should prompt a field info cache clear, that seems like a very rare thing to add, presumably it'd already need to alter the entity info cache too?

RAM consumption - I don't really know, it's possible that some variables are built in the un-cached run which don't make their way into the returned data, and that PHP garbage collection isn't dealing with them properly. If someone's able to reproduce the test on PHP 5.3 (which I don't have locally) that'd be an interesting comparison since garbage handling is very different afaik.

It's also possible that xhprof measurement either skews the memory usage just by virtue of measuring it, or is otherwise imperfect.

If I get some time tomorrow, I'll try to re-roll the original patch with the attempt at memory savings, and see if it makes any difference in either case.

Updated patch which tries to make the array smaller as with #1. Combined with the caching, it looks like a further improvement although the numbers are a bit odd. Everything seems a bit more expensive this round of profiling, not really sure why that is, but attached xhprof screenshots of the various combinations including previous patch to compare like with like.

Also confirmed a lot of the memory and cpu on cache hits is from unseriaiizing the cache entry, so sites using pluggable cache.inc should skip a lot of that.

field_info_fields() is only called by file_get_references() - http://api.drupal.org/api/function/field_info_fields/7 - and file_get_references() is a bad example for many different things with at least two critical bugs against it, so I'm happy for a bit of memory bloat in that function to avoid it in the critical path, or thinking about it, we could just not static cache it and do the foreach each time, the foreach just by itself on a few requests doesn't need caching.

All the other comments fully agreed with, I'll re-roll today, and do one more set of profiling - xdebug on the real site (with 295 instances and memcache) and xhprof with a more reasonable 100 fields on HEAD.

Updated patch per #21, more (hopefully last round) profiling soon.

OK so with ~295 instances and memcache, here's the before and after - xdebug says 20% of page request down to 1% - the reason this is so much more dramatic is 'cos we save the unserialize() when using memcache. No memory output from xdebug/webgrind and I don't have xhprof on there.

Devel output though:

With patch: age execution time was 515.65 ms. Memory used at: devel_boot()=5.17 MB, devel_shutdown()=45.28 MB, PHP peak=46.5 MB.

Without patch: Page execution time was 601.76 ms. Memory used at: devel_boot()=5.17 MB, devel_shutdown()=46.45 MB, PHP peak=47.5 MB.

So at most 1mb saving (not sure how much that's out of though). Still plenty from one function.

#23: field_info.patch queued for re-testing.