Comments

torgospizza’s picture

joelpittet’s picture

Status: Active » Needs review

Do you know how many times it gets called on your site average/rough numbers on the high end(maybe a listing page)?

joelpittet’s picture

The diff looks poorly so I thought I'd show a non-whitespace version.

-  $extra = array();
-
+  $extra = &drupal_static(__FUNCTION__);
+  if (!isset($extra)) {
     // Loop through the product reference fields.
     foreach (commerce_info_fields('commerce_product_reference') as $field_name => $field) {
       foreach ($field['bundles'] as $entity_type => $bundles) {
@@ -105,6 +105,7 @@ function commerce_product_reference_field_extra_fields() {
         }
       }
     }
+  }



joelpittet’s picture

My page gets about 250 calls to t from within that function.

Also could we avoid the giant nesting if by returning the cached version at the top of the function or preceeding as normal. It would make this patch easier to read and hopefully make it easier to maintain as well.

joelpittet’s picture

Status: Needs review » Needs work
torgospizza’s picture

Status: Needs work » Needs review
StatusFileSize
new156.63 KB
new221.1 KB
new623 bytes

Running into this issue again and want to work on a new patch. We're getting 106 calls to this function on a Panelized product node page. There are blocks containing poster images of products on each product page but those are just fields returned from Solr. Here is the transaction flow from New Relic:

Panelizer is calling panelizer_entity_view_alter() from the usual drupal_alter() after node_view().
panels_renderer_standard::prepare_panes calls ctools_entity_field_content_type_content_types()
Which then calls field_info_extra_fields() followed by commerce_product_reference_field_extra_fields() from module_invoke_all().

The hook field_info_extra_fields() is called 106 times (!) according to New Relic. Each call takes around 28ms. Multiply that times 100 and you've got almost 3 seconds of CPU burn. This is even with Memcache enabled.

Attached are some screengrabs of what New Relic is reporting, as well as a new patch that simply checks for the static variable and if found returns it.

Status: Needs review » Needs work

The last submitted patch, 6: commerce_product_reference-static-2389573-6.patch, failed testing.

joelpittet’s picture

Status: Needs work » Needs review
StatusFileSize
new672 bytes

Strange that didn't apply. This it just has one extra context line.

Status: Needs review » Needs work

The last submitted patch, 8: commerce_product_reference-static-2389573-8.patch, failed testing.

The last submitted patch, 6: commerce_product_reference-static-2389573-6.patch, failed testing.

joelpittet’s picture

Well it seems that maybe some conditions may be call dependent? Or else why would this fail to produce the data for that test?

torgospizza’s picture

Some more data, profiling this in XHProf I see almost a full 1 second decrease in processing time with the patch. Which makes sense since the initial call probably takes some time to run, but then it doesn't need to run for any subsequent calls.

Before:
Total Incl. Wall Time (microsec): 2,672,861 microsecs
Total Incl. MemUse (bytes): 90,387,616 bytes
Total Incl. PeakMemUse (bytes): 92,918,192 bytes

After:
Total Incl. Wall Time (microsec): 1,509,006 microsecs
Total Incl. MemUse (bytes): 90,089,496 bytes
Total Incl. PeakMemUse (bytes): 93,118,136 bytes

Not sure why the test is failing. In my local and development/staging servers, the Product Reference fields are definitely visible in the Content Types field management area, so my guess is maybe the test itself isn't written in the best way.

Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, 8: commerce_product_reference-static-2389573-8.patch, failed testing.

joelpittet’s picture

@torgosPizza That test is probably a saving grace when it comes to adding static variables. The case is probably the extra fields is called, the new product display with reference field is added and then going to that same page in the same request.

You could change the test, but safer bet would be reset that static cache when fields are saved/deleted? What do you think?

rszrama’s picture

I wonder if this function gets called before data is available in some cases, resulting in that $extra array being empty the first go round and populated on subsequent requests. : ?

torgospizza’s picture

Issue tags: +Commerce Sprint

This is one of those patches that helped us out a great deal, so I'm tagging for some sprint time.

mglaman’s picture

Status: Needs work » Needs review
StatusFileSize
new673 bytes

Same as #8, but uses !empty instead of isset. The variable is always set, and this should catch any wonkiness if it passes through as empty once, or something.

joelpittet’s picture

@mglaman weird because the docs use isset() checks. https://api.drupal.org/api/drupal/includes!bootstrap.inc/function/drupal...

mglaman’s picture

Well isset() works if it is NULL, however what if it randomly gets an empty array set (#17)

torgospizza’s picture

Right, but if there are no extra fields to populate that array, then shouldn't the empty array be what gets statically cached? Perhaps I don't know enough about this particular function.

EDIT to add, it is interesting that the patch passes now.

mglaman’s picture

I think the test patches passes because the test is written wrong, for what it's worth.

heathdutton’s picture

Using #19 in production right now, because commerce_product_reference is currently one of the slowest modules according to NewRelic. It's still not great though. Any other ideas on how we can boost perf of this module?

mglaman’s picture

Issue summary: View changes
Status: Needs review » Needs work
StatusFileSize
new47.1 KB
new33.71 KB

Needs work. #19 doesn't do anything special. #8 does. Attaching initial Blackfire reports pre patch and post. Did simple profiling off of demo CK2 install of /tops/guy-short-sleeve-tee.

Pre

Post

However, disclaimer, my env has xhprof and xdebug enabled, so some things might be skewed. but there is a win. Test just needs to be fixed.

torgospizza’s picture

Very interesting. And yeah the #8 patch helped us out boat loads. The test failure still concerns me, but I liked @joelpittet's suggestion of clearing field caches after one of those $op calls.

Should we submit for a re-test?

mglaman’s picture

Confirming the test is the problem, see commerce_product_field_extra_fields().

function commerce_product_field_extra_fields() {
  $extra = &drupal_static(__FUNCTION__);

  if (!isset($extra)) {
mglaman’s picture

Status: Needs work » Needs review
StatusFileSize
new1.9 KB
new1.79 KB

Here is updated test which actually retrieves the field attach properly. This should do it!

mglaman’s picture

StatusFileSize
new1.7 KB
+++ modules/product_reference/commerce_product_reference.module
@@ -36,14 +36,12 @@ function commerce_product_reference_commerce_product_uri($product) {
-  $extra = &drupal_static(__FUNCTION__);
+  $extra = &drupal_static(__FUNCTION__, array());
...
-  $extra = array();
-

I'm stupid here. It's set then by providing default return value.

The last submitted patch, 28: use_a_static_cache_in-2389573-28.patch, failed testing.

Status: Needs review » Needs work

The last submitted patch, 29: use_a_static_cache_in-2389573-29.patch, failed testing.

mglaman’s picture

Status: Needs work » Needs review
StatusFileSize
new1.71 KB

I don't know what I did to make these patches hate me.

Status: Needs review » Needs work

The last submitted patch, 32: use_a_static_cache_in-2389573-32.patch, failed testing.

mglaman’s picture

Status: Needs work » Needs review
StatusFileSize
new1.13 KB
new1.72 KB

Test should be fixed now to get extra field info properly.

joelpittet’s picture

Status: Needs review » Needs work
+++ b/modules/product_reference/commerce_product_reference.module
@@ -36,6 +36,12 @@ function commerce_product_reference_commerce_product_uri($product) {
 function commerce_product_reference_field_extra_fields() {

+++ b/modules/product_reference/tests/commerce_product_reference.test
@@ -262,8 +262,9 @@ class CommerceProductReferenceAdminTest extends CommerceBaseTestCase {
-    $extra_fields = commerce_product_reference_field_extra_fields();
-    foreach ($extra_fields['node'][$this->display_type->type]['display'] as $display) {
+    $extra_fields = field_info_extra_fields('node', $this->display_type->type, 'display');
+
+    foreach ($extra_fields as $display) {

This looks to be the only test for that function it could be a bad test or something it's hard to tell but removing the function call is sketch as the solution.

mglaman’s picture

call is sketch as the solution.

How? It's a hook invocation. The test is now properly invoking the hook like the system typically would.

torgospizza’s picture

Agree with @mglaman.

I would imagine invoking field_info_extra_fields() is more correct than calling commerce_product_reference_field_extra_fields() directly. This is because commerce_product_reference_field_extra_fields() is an implementation of the hook which is meant to be called by module_invoke_all as part of the hook process, and AFAIK would not be called directly. I've never seen a direct call to a hook implementation / function before in practice, and so using that in a test also doesn't make sense to me. That's why they're hooks! So we don't have to call them at all! :)

joelpittet’s picture

Status: Needs work » Needs review

Oh you are both right, sorry didn't realize it was a hook. Sorry.

torgospizza’s picture

No worries :)

I'd mark this RTBC but it's my issue and (original) patch. However the performance gains still stand for us. Production hasn't been without this patch since I wrote it!

joelpittet’s picture

Status: Needs review » Reviewed & tested by the community
StatusFileSize
new61.86 KB
new33.7 KB

So yeah that test needs to be getting everything provided by that hook.



torgospizza’s picture

Love it. Thanks Joel!

mglaman’s picture

:) Yeah I don't get how this test was even working before by calling it direct. I think that's why static cache broke it. I think a call within the method built the field cache class and something goofy happened. But calling it properly has everything primed.

rszrama’s picture

Status: Reviewed & tested by the community » Fixed

Boom. Committed.

  • rszrama committed 86d6784 on 7.x-1.x authored by torgosPizza
    Issue #2389573 by mglaman, torgosPizza, joelpittet: Use a static cache...

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.