As with the issue in #2354561: Use a static cache in commerce_product_field_extra_fields() the function field_info_extra_fields() gets called a LOT and having Commerce's implementation of these hooks use a static cache shows a nice increase in performance.
I think it'd be beneficial to statically cache this function in the Product Reference module as well.
Attached is my first attempt at a patch, would love feedback.
| Comment | File | Size | Author |
|---|---|---|---|
| #40 | Test_result___broke.png | 33.7 KB | joelpittet |
| #40 | Test_result-fixed.png | 61.86 KB | joelpittet |
| #34 | use_a_static_cache_in-2389573-34.patch | 1.72 KB | mglaman |
| #34 | interdiff-2389573-32-34.txt | 1.13 KB | mglaman |
| #28 | interdiff-2389573-8-28.txt | 1.9 KB | mglaman |
Comments
Comment #1
torgospizzaComment #2
joelpittetDo you know how many times it gets called on your site average/rough numbers on the high end(maybe a listing page)?
Comment #3
joelpittetThe diff looks poorly so I thought I'd show a non-whitespace version.
Comment #4
joelpittetMy 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.
Comment #5
joelpittetComment #6
torgospizzaRunning 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.
Comment #8
joelpittetStrange that didn't apply. This it just has one extra context line.
Comment #12
joelpittetWell it seems that maybe some conditions may be call dependent? Or else why would this fail to produce the data for that test?
Comment #13
torgospizzaSome 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.
Comment #16
joelpittet@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?
Comment #17
rszrama commentedI 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. : ?
Comment #18
torgospizzaThis is one of those patches that helped us out a great deal, so I'm tagging for some sprint time.
Comment #19
mglamanSame as #8, but uses
!emptyinstead ofisset. The variable is always set, and this should catch any wonkiness if it passes through as empty once, or something.Comment #20
joelpittet@mglaman weird because the docs use
isset()checks. https://api.drupal.org/api/drupal/includes!bootstrap.inc/function/drupal...Comment #21
mglamanWell isset() works if it is NULL, however what if it randomly gets an empty array set (#17)
Comment #22
torgospizzaRight, 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.
Comment #23
mglamanI think the test
patchespasses because the test is written wrong, for what it's worth.Comment #24
heathdutton commentedUsing #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?
Comment #25
mglamanNeeds 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.
Comment #26
torgospizzaVery 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?
Comment #27
mglamanConfirming the test is the problem, see commerce_product_field_extra_fields().
Comment #28
mglamanHere is updated test which actually retrieves the field attach properly. This should do it!
Comment #29
mglamanI'm stupid here. It's set then by providing default return value.
Comment #32
mglamanI don't know what I did to make these patches hate me.
Comment #34
mglamanTest should be fixed now to get extra field info properly.
Comment #35
joelpittetThis 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.
Comment #36
mglamanHow? It's a hook invocation. The test is now properly invoking the hook like the system typically would.
Comment #37
torgospizzaAgree 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! :)
Comment #38
joelpittetOh you are both right, sorry didn't realize it was a hook. Sorry.
Comment #39
torgospizzaNo 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!
Comment #40
joelpittetSo yeah that test needs to be getting everything provided by that hook.
Comment #41
torgospizzaLove it. Thanks Joel!
Comment #42
mglaman:) 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.
Comment #43
rszrama commentedBoom. Committed.