When loading the default taxonomy/term/n view provided with views, unpack_options() is called 172 times, taking 29ms (on the example page I loaded on my laptop) - this makes it the most expensive function on the page most of the time.

unpack_options() calls itself recursively - hence so many function calls, but it also appears to be called a lot more times than it's supposed to.

Looking through a bit, I'm fairly sure the main culprit is $view->set_display - this gets called four times:

views_arg_load 2
view->execute_display 1
views_plugin_display_feed->attach_to 1

This in turn calls view->init_display 4 times

(which calls views_plugin_display->init 16 times, which calls unpack_options 16 times - but there's only four displays to do this for in that view).

So it looks like on that particular view, the same work is being done four times. If we can somehow set it up so ->set_display only runs once per view, I think that'll cut 75% of the time.

merlinofchaos suggested views_arg_load() could be used only for tabs - that'd help too, but I think it's an aggravating factor here rather than the root cause - views_arg_load() isn't the only place causing duplicate processing.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

sdboyer’s picture

I also noticed this on a major production site; in that case, unpack_options was being called a couple thousand times, and was occupying some 30-40% of overall page execution time. We hadn't had time to backtrace through it, but we did start kicking around some other ways to possibly make the operation itself slightly less expensive.

All of which is to basically say, 'subscribe' :)

zengenuity’s picture

Yeah. It's accounting for 26% percent of my page load on a panels page that loads few view panes. Subscribing.

dawehner’s picture

FileSize
122.52 KB
99.2 KB

i have a site with quite a lot of views (20 with different displays etc.) embedded in 15 panels.

just to give some more informations there is a webgrind screenshot attached. Then i thought using a normal php function instead of a class-method would perhaps speed up things, but not really a lot, see second screenshot.

@catch
Can you tell me how you make your full-webpage screenshot of webgrind?

Thats basically quite a lot of text for subscribing :)

catch’s picture

@dereine, I use the 'screengrab' extension for firefox, very handy.

chx’s picture

Any progress in here? How can I help?

catch’s picture

The immediate thing to do would be stop using menu loaders for views across the board - since views_load() not only loads the view, but also builds it partially, and isn't statically cached, that results in duplicate processing whenever it happens - and appears to be the default behaviour for some views paths.

The next thing would be only doing unpack_options() once for the same view with the same arguments etc., but that's a lot more involved and likely needs some refactoring - however switching away from the menu loader to a regular wildcard would at least make it easier to see what's left.

Mixologic’s picture

Okay, so I ended up on this thread as I too have a gargantuan cachegrind file thats about 50% views_unpack_options.

Catch: when you say 'stop using menu loaders for views', can you point me in a place where I can make that happen? Im not exactly sure where that'd be. Our 100 + menu is pointing at two different views that take 4 or 5 args, and its simply boggling the amount of slog thats happening as a result (5-6 second page view times)..

catch’s picture

@Mixologic - look at views_menu_alter() and views_arg_load() - views_arg_load() gets the view and does things like ->set_display(), the problem is that menu access callbacks, help module and many other kinds of things can end up calling that menu loader via different code paths - since it's not static cached the same code gets executed multiple times. I didn't profile a lot of different views, just one simple one iirc, but you want to trace up from unpack_options in that cachegrind to confirm if there's more than one call to views_arg_load() - if there is then that's the first place to look to optimize this since it's doing exactly the same work twice (although equally double check which arguments are sent in to views_arg_load() - in my example it was the same, might not be for yours).

Mixologic’s picture

Awesome. I think I narrowed this done finally, and I think its a bug in menu_link_translate function in menu.inc, either that or views is failing to do something its supposed to.

So the callstack in question is doing something like this:
menu_tree_all_data($menu_name)->menu_tree_check_access($tree, $node_links)->_menu_tree_check_access(&$tree)->_menu_link_translate($item)

Line 656 of menu.inc (inside of menu_link_translate) has the following:

if (!isset($item['access'])) { //This if statement is assuming that if the access isnt set, the object isnt already loaded.
      if (!_menu_load_objects($item, $map)) {
        // An error occurred loading an object.
        $item['access'] = FALSE;
        return FALSE;
      }
      _menu_check_access($item, $map);
    }

The issue that im running into is that way back in menu_tree_all_data, my whole menu tree is pulling from menu_cache like it should, and all the items on that tree are already loaded, and thus they dont need to get loaded again here. Which since I have about 105 menu items that all point at 2 different views that each take up to four arguments, 402 calls to views_load_arg was happening on every page load.

The only apparent reason that _menu_load_objects is called here is to get the access_callback set on $item so it can do the _menu_check_access call (though there may be other reasons not obvious to me of course).

I changed my code to the following and kapow.. my cachegrind file went from 338mb to 12 mb. Oh, and my *extremly complicated* views menu now displays in about 2 seconds instead of two minutes.

 if (!isset($item['access'])) {
    	if(!isset($item['access_callback'])){
          if (!_menu_load_objects($item, $map)) {
            // An error occurred loading an object.
            $item['access'] = FALSE;
            return FALSE;
          }
    	}
      _menu_check_access($item, $map);
    }

Is there a better way to determine if the menu item is already loaded? Thanks for your help y'all.

Also, I check D7 Head, and at line 795 its pretty much the same, with the addition of a check to see if the "load_functions" is set:

if (!isset($item['access'])) {
796	      if (!empty($item['load_functions']) && !_menu_load_objects($item, $map)) {
797	        // An error occurred loading an object.
798	        $item['access'] = FALSE;
799	        return FALSE;
800	      }
801	      _menu_check_access($item, $map);
802	    }
mikeytown2’s picture

Title: unpack_options() is expensive » _menu_link_translate calls _menu_load_objects unnecessarily.
Project: Views (for Drupal 7) » Drupal core
Version: 6.x-2.x-dev » 6.x-dev
Component: Code » menu system
Issue tags: +Performance
FileSize
2.33 KB

Patch for _menu_link_translate() in core based off of #9. In short it checks to make sure $item['access_callback'] is not set before calling _menu_load_objects(). Fix makes sense.

Damien Tournoud’s picture

Status: Active » Closed (duplicate)
Damien Tournoud’s picture

Also see #238695: Document static cache requirements for menu loaders. In a nutshell: Views has to static cache its loaders (if not already done now, this is has been known for quite some time...).

mikeytown2’s picture

Title: _menu_link_translate calls _menu_load_objects unnecessarily. » unpack_options() is expensive. Views needs to static cache its loaders.
Project: Drupal core » Views (for Drupal 7)
Version: 6.x-dev » 6.x-2.x-dev
Component: menu system » Code
Status: Closed (duplicate) » Active

@Damien Tournoud
Thanks for pointing out the dup #753064: _menu_link_translate() might avoid calling _menu_load_objects()

Moving this back to views, and refocusing this to static caching in views.

drewish’s picture

Status: Active » Needs review
FileSize
1.04 KB

On one of my sites we were getting killed on this but I traced it back to panels calling views_block() on every page load. views_block() iterates over every view and calls $view->init() so it can build a list of blocks and their titles.

Merlin suggested just caching the list of items. On my site it knocked a full second off my page render times. I'm assuming that Views will take care of calling cache_clear_all() when a view changes.

drewish’s picture

FileSize
944 bytes

The previous patch applies with an offset to 6.x-3.x.

I did a quick copy/paste job to 7.x-3.x but didn't test it.

locomo’s picture

subscribe

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

Patch works fine.

You shouldn't have "Disable views data caching" enabled :)

Thanks!! for a patch for the drupal7 version.

brianV’s picture

Semi-related patch to static cache views_arg_load() data: #881468: Performance: Static cache output of views_arg_load()

merlinofchaos’s picture

Status: Reviewed & tested by the community » Fixed

Fantastic. Committed to all branches. Thanks!

Status: Fixed » Closed (fixed)

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

datarazor’s picture

Status: Closed (fixed) » Needs review
FileSize
59.57 KB

I just want to mention that many months have gone bye since:

#9 Mixologic's suggested fix, but there has been no adoption of this code in D6.20, nor in My views is version 2.12. And at the time of writing, both of these modules are up-to-date.

My website was having horrible page loads times which were only made apparent after we had to move servers, I applied the changes to menu.inc in .includes

if (!isset($item['access'])) {
    if(!isset($item['access_callback'])){
          if (!_menu_load_objects($item, $map)) {
            // An error occurred loading an object.
            $item['access'] = FALSE;
            return FALSE;
          }
    }
      _menu_check_access($item, $map);
    }

And my website now loads node/edit forms in 6 to 8 seconds instead of 22 to 32 seconds!!

156,000 functions called to render the page instead of 1,734,000 functions!!
...a 91.1% reduction

which is huge!!

I seriously hope that this performance improvement can be included in D6.21 as I have lost about a month's work looking everywhere for the possible cause and after many failed directions had to eventually set up xhprof to pinpoint it.

Thank you!

EDIT: and yes: my Views are set to cache, if anyone wonders ;-)

dawehner’s picture

Status: Needs review » Closed (fixed)

As you can read(not nobody does) in the release announcement views 6.12 was a security-only release.

This patch is already in the dev version of views and can be used there.

If you think this should be in the stable version please help us to fix other issue in the views issue queue.
Go through the issue: take one issue and try to solve it.

This could include a patch, answer a support request, mark it as duplicate etc. There are many ways/opportunities to help
Resetting status.

datarazor’s picture

Hell Dereine,

Thank you for your speed reply. When I saw that a possible solution to this issue was report in March of 2010 [nearly a year ago], and that it was then committed as a fix to Views in August 12, 2010, and then set to "closed --> fixed". Well, that's looks to me as if it should be in a production release! As I find it hard to believe that such a "critical" performance-void as this, was not considered as important as a security release.

I have a question about ticket-settings. When the fix goes from 6.x.2.x-dev to 6.x-2.13, will the Version field of this ticket be changed to reflect that?

Perhaps to not confuse others, it would make sense to have a status of a ticket set to something other than "closed (fixed)" when in fact the issue is still in DEV and not in a stable release? Maybe "closed (fixed-dev / pending-release)"??

Just a thought.

Apologies for not realizing this is in a DEV release of Views. In any case I am just happy that I found where the issue was!

Sincerely,

datarazor

merlinofchaos’s picture

d.o currently has no automatic tying of releases to tickets (I suggested it once, I think there's an issue in the project queue). Additionally, when an issue is marked 'fixed' d.o makes it closed (fixed) 2 weeks later automatically. These are both project.module deficiencies and as maintainers we simply have to live with the decisions or put in the time and effort to help dww change project.module.

mikeytown2’s picture

Status: Closed (fixed) » Needs work
FileSize
1 KB

I'm currently investigating this as this is still an issue on our setup; using the latest views dev. Need to make sure the cache ID is unique enough; or maybe it can be built in a better way. Here is the test code I got so far. This reduces total execution time by 400ms on our setup according to cache grind. This is test code; will make it better if people think this is the right approach for this issue.

    // Cache for unpack_options.
    static $unpack_options = array();
    $cid = md5($view->db_table . ' ' . $view->base_table . ' ' . $view->name . ' ' . $view->current_display . ' ' . serialize($options));
    if (empty($unpack_options[$cid])) {
      $data = cache_get($cid);
      if (!empty($data->data)) {
        $this->options = $data->data;
      }
      else {
        $this->unpack_options($this->options, $options);
        cache_set($cid, $this->options, 'cache', CACHE_TEMPORARY);
      }
      $unpack_options[$cid] = $this->options;
    }
    else {
      $this->options = $unpack_options[$cid];
    }
catch’s picture

Caching the actual options is interesting, ages ago I tried to cache this at a much higher level but didn't get very far, if we can add it here then the only issue is as you say getting the $cid granular enough.

dawehner’s picture

+++ b/plugins/views_plugin_display.incundefined
@@ -39,7 +39,23 @@ class views_plugin_display extends views_plugin {
+    if (empty($unpack_options[$cid])) {
+      $data = cache_get($cid);
+        cache_set($cid, $this->options, 'cache', CACHE_TEMPORARY);
   }
 
   function destroy() {

What about using views_cache_set, so language is automatically part of the cid?

mikeytown2’s picture

@dereine
We'll get there once we have a better $cid ;)

I was thinking about this more, what if the $cid was used as a sudo lookup table in order to try to get higher cache hits & thus better performance. I'll need to profile this to see if sorting gets me a better hit ratio.

$a = asort($this->options);
$b = asort($options);
$cid = md5(serialize($a) . serialize($b));
dawehner’s picture

Oh sure in general i'm wondering why this isn't part of the main unpack_options in includes/base.inc

unpack_options is called on things other then displays as well, for example all handlers.
This would solve the problem quite generic, but then some kind of context would be needed here.

mikeytown2’s picture

Status: Needs work » Needs review
FileSize
967 bytes

asort() doesn't work in this case.

$cid = md5(serialize($this->options) . serialize($options)); has the same cache hit ratio as $cid = md5($view->db_table . ' ' . $view->base_table . ' ' . $view->name . ' ' . $view->current_display . ' ' . serialize($options));, so I'm going opt for serialize only as this seems to be safer.

Placing the caching logic inside unpack_options() gives no speed improvement; doing so increased the calls to cache_get from 169 to 303. I tested out expanding the recursion to 3 levels because, you know function calls in php aren't cheap and that didn't gain me much. So all said and done, placing the cache in views_plugin_display init seems to be the best option.

Here is the patch for review.

mikeytown2’s picture

Been running with the above patch for the last 3 days in production (2 code bases, 77 databases, 1284 domains) and no issues have shown up.

crea’s picture

Subscribing

catch’s picture

FileSize
1.01 KB

Looking at the distribution of calls, from a performance point of view this is the right place to cache (unless we were able to cache the view at a much higher level but when I tried that a year or so ago I came up short).

Profiling a client site with and without the patch applied:

Before:
6877 calls to unpack_options()

After:
329 calls to unpack options
Additional 24 calls to cache_get()

I'm uploading a re-rolll for the 6.x-3.x branch.

mikeytown2’s picture

Think we can call this RTBC?
#31 for 6.x-2.x
#34 for 6.x-3.x

catch’s picture

Title: unpack_options() is expensive. Views needs to static cache its loaders. » Persistent caching for unpack_options() calls from building displays
Version: 6.x-2.x-dev » 6.x-3.x-dev
Status: Needs review » Reviewed & tested by the community

Yeah I agree, after 2.5 years this really looks like the best option, and I don't see caching at a higher level being possible without refactoring, whereas this is just a few lines of code.

dawehner’s picture

Assigned: Unassigned » merlinofchaos

This will not get all unpack_options which are availible. It might make sense to add this to views_handler as well.
I'm not 100% sure whether this is true or not

This patch looks fine and got tested by quite some people. Assign for merlinofchaos as this would be cool to get some feedback.

catch’s picture

Earl asked in irc about the number of cache_get() calls here. While it should be a decent trade off even with database caching it can be a fair bit.

One way to reduce that would be to use DrupalCacheArray. This would allow for a cache entry per view, instead of a cache entry per options key - so would reduce the calls to both cache_set() and cache_set().

That's in Drupal 7 now so would be available to 7.x-3.x. For 6.x-3.x/2.x it's the same PHP5 issue as #853864: views_get_default_view() - race conditions and memory usage in terms of ArrayAccess so it'd be a bit trickier.

I don't want to derail this patch going in as is, but I'd be up for working on that either here or in a followup issue.

mikeytown2’s picture

@catch
D6 - What if we save the cache as a shutdown function? Get lock, read current cache, merge in changes, save, & release lock. Shutdown function gets triggered if we have a cache miss. Over time we get a 100% cache hit rate but our memory usage goes up; but I think this would be a good trade off. Cache per view is where I would start due to memory concerns.
D7 - DrupalCacheArray sounds like a nice abstraction that will do what we need.

The patch as it stands gives a nice speed improvement; the gains from optimizing cache_get calls won't be as big of a win & will add in some complexity. +1 for a follow up issue if we don't come up with a simple solution for the multitude of cache_get calls.

mikeytown2’s picture

Here's a proof of concept patch for the shutdown cache merge idea. I've tested it with caching core's URL function: #1327720: Cache url()

mikeytown2’s picture

Status: Reviewed & tested by the community » Needs review
FileSize
3.17 KB
2.57 KB

Note: The 6.x-3.x patch is untested, but should work; The 6.x-2.x patch is tested.

Stock:
Total Self: 459ms
Total Cumulative: 1,241ms
Memcache->get calls: 209
views_object->unpack_options calls: 3,794

Patch #31:
Total Self: 130ms
Total Cumulative: 206ms
Memcache->get calls: 240
views_object->unpack_options calls: 1,047

CID - global (patch not included):
Total Self: 27ms
Total Cumulative: 217ms
Memcache->get calls: 233
views_object->unpack_options calls: 515

CID - per view (this patch):
Total Self: 27ms
Total Cumulative: 134ms
Memcache->get calls: 274
views_object->unpack_options calls: 515

mikeytown2’s picture

Status: Needs review » Reviewed & tested by the community

#41 doesn't perform well on a production environment; cache_get is too slow. If it only cached larger/slower objects then it might be faster; we serialize it so we can get an estimate on how big the object will be.

At any rate, putting this back to RTBC:
#31 for 6.x-2.x
#34 for 6.x-3.x

mikeytown2’s picture

Status: Reviewed & tested by the community » Needs review
FileSize
4.31 KB

Stock:
Total Self: 610ms
Total Cumulative: 1,741ms
Memcache->get calls: 212
views_object->unpack_options calls: 5,284

In-lined function:
Total Self: 521ms
Total Cumulative: 583ms
Memcache->get calls: 212
views_object->unpack_options calls: 569

#31:
Total Self: 123ms
Total Cumulative: 201ms
Memcache->get calls: 264
views_object->unpack_options calls: 936

#31 & In-lined function (this patch):
Total Self: 111ms
Total Cumulative: 137ms
Memcache->get calls: 264
views_object->unpack_options calls: 358

Creating an in-lined 3.x patch is possible, it will be more messy though.

msonnabaum’s picture

Here's a version against the current 7.x-3.x. Seems to be working well.

mikeytown2’s picture

If anyone is wondering #44 is based off of #31/#34. This code path is RTBC. #43 is testing how much getting rid of recursion speeds up unpack_options; that patch is a combo patch and is still under needs review.

msonnabaum’s picture

Version: 6.x-3.x-dev » 7.x-3.x-dev
FileSize
1.1 KB

Added a check to prevent caching when editing a view per dereine's request.

dawehner’s picture

Status: Needs review » Needs work
FileSize
1.25 KB
+++ b/plugins/views_plugin_display.incundefined
@@ -50,7 +50,24 @@ class views_plugin_display extends views_plugin {
+      if (!empty($cache->data) && !$view->editing) {
+        $this->options = $cache->data;
+      }
+      else {
+        $this->unpack_options($this->options, $options);
+        views_cache_set($cid, $this->options, TRUE);

This still sets one cache entry everytime you do something in the ui

dawehner’s picture

Status: Needs work » Needs review

Update status.

msonnabaum’s picture

Status: Needs review » Reviewed & tested by the community

Makes sense. Cleaner than mine.

dawehner’s picture

Status: Reviewed & tested by the community » Fixed

Awesome.

Thanks everyone involved in that issue
Committed this patch to both 6.x-3.x and 7.x-3.x.. Just if someone asks, no there will be no 6.x-2.x patch here.

@mikeytown2
If you think that your patch would be a great addition as well, you could create a new issue, so it's much easier to keep track of.

mikeytown2’s picture

Patch for 6.x-2.x based off of #47 for those of us who are still on views 2.

Also created #1372388: Inline/Remove recursion in views_object->unpack_options to improve performance

mstef’s picture

Patch that applies against 7.x-rc1 - needed for drush make.

Status: Fixed » Closed (fixed)
Issue tags: -Performance

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