While profiling D7, I noticed that _menu_check_access() is called many many times with paths that have no relevance to the current page. This function is in the top 5 time sucks right now.

To reproduce the problem:

  1. Ideally, start with clean HEAD install
  2. Create a standard user and login as that user
  3. Add this line to top of _menu_check_access(): print ($item['href']) . "\n";
  4. View homepage and note all the strange paths that get checked like taxonomy/autocomplete and user field/js_add_more system/ahah
Files: 
CommentFileSizeAuthor
#35 drupal.toolbar-depth.patch1.18 KBsun
Passed: 14475 passes, 0 fails, 0 exceptions
[ View ]
#34 depth-519046-34.patch1.01 KBpwolanin
Passed: 14478 passes, 0 fails, 0 exceptions
[ View ]
#30 insure-pop-519046-29.patch1.04 KBpwolanin
Failed: 13657 passes, 0 fails, 2 exceptions
[ View ]
#26 head.png368.58 KBcatch
#26 patch.png352 KBcatch
#26 toolbar_access_menu_load.png591.08 KBcatch
#22 head.png347.23 KBcatch
#22 patch.png350.61 KBcatch
#21 fewer-access-calls-519046-21.patch1.34 KBpwolanin
Failed: Failed to apply patch.
[ View ]
#19 cache.patch8.03 KBcatch
Failed: Failed to apply patch.
[ View ]
#17 cache.patch8.03 KBcatch
Failed: Invalid PHP syntax in modules/user/user.admin.inc.
[ View ]
#14 cache.patch8.03 KBcatch
Failed: Invalid PHP syntax in modules/system/system.module.
[ View ]
#12 cache.patch4.9 KBcatch
Failed: Failed to apply patch.
[ View ]
#11 cache.patch3.4 KBcatch
Failed: Failed to apply patch.
[ View ]
#7 cache.patch3.4 KBcatch
Failed: Invalid PHP syntax in modules/toolbar/toolbar.module.
[ View ]
#6 patch.png380.37 KBcatch
#6 head.png413.8 KBcatch
#6 cache.patch3.55 KBcatch
Failed: Invalid PHP syntax in modules/toolbar/toolbar.module.
[ View ]
#6 patch_incl.png380.62 KBcatch
#6 head_incl.png343.32 KBcatch

Comments

discussed in IRc - sounds like a bug

Issue tags:+Performance

Silly placeholder because I have to say something when adding a tag.

subscribing.

That's very odd. The ones that have me really puzzled are:
My user can't create that content type, much less delete it.
admin/structure/node-type/article/delete
admin/structure/node-type/page/delete

It's checking access to see if that page is accessible to the user or not, to decide whether to render the menu link for 'structure', which should only show up if there's at least one item that user has access to underneath it.

And yes, this is really stupid and wasteful to be doing that on every page request.

Component:menu system» toolbar.module
Status:Active» Needs review
StatusFileSize
new343.32 KB
new380.62 KB
new3.55 KB
Failed: Invalid PHP syntax in modules/toolbar/toolbar.module.
[ View ]
new413.8 KB
new380.37 KB

This is caused by having toolbar.module (or anything which tries to get the entire admin menu tree on non-admin pages) enabled.

Attached patch doesn't fix the root cause, since I can't think of a good way to do that, but it fixes the performance issue and has the side-effect of speeding up /admin too.

I added a cache for system_admin_menu_block() based on $item['path'] (while it's not guaranteed to be unique, people who put two links to the same path at the top of /admin and expect it to work I have no interest in making their lives easier), and implode('|', array_keys($user->roles)); - so we get a cache entry per block, per combination of roles.

This makes system_admin_menu_block_access() require a cache_get() instead of two direct queries and a bunch of access checking of large arrays, not perfect, but better.

Additionally, I added a similar cache for the result of toolbar_get_menu_tree() - since that also triggers access checks on the entire admin menu structure as well, which was taking up 25% of page execution time by itself, and without both, we end up with no real gains here.

webgrind looks happier, attached screenshots ordered by both self and incl.

@TODO, clearing the new cache. It needs to be cleared on at least:

# saving the permissions page
# saving a new menu link and/or menu_rebuild() - might be covered by existing cache clears?

but marking as needs review for the bot/concept.

StatusFileSize
new3.4 KB
Failed: Invalid PHP syntax in modules/toolbar/toolbar.module.
[ View ]

Putting back a useful if check.

Status:Needs review» Needs work

The last submitted patch failed testing.

@catch - so this is basically due to some badly coded new core code?

Title:too many calls to _menu_check_access()Too many calls to _menu_check_access()

@pwolanin, well, yes.

#296693: Hide empty admin categories was committed months ago, which was supposed to hide menu links for empty admin categories, but obviously didn't take into account that this check would be done on every page which might ever possibly want to display one of those links. Since the toolbar does the equivalent of setting 'admin' to expanded, we're now effectively rendering the entirety of /admin on every page request just to hide a couple of links. This isn't the fault of toolbar.module and it affects admin_menu.module as well in contrib (except admin_menu does client-side caching in D7 so mitigates the worst of this), or the management menu if you set admin to expanded in the menu UI, so needs to be fixed in system.module.

#520364: system_admin_menu_block_access() makes no sense exists to fix this stupidity properly, but I don't want to clutter that one with this workaround, since it's possible someone will come up with a proper fix there - after which this would be easy to revert if we don't think it's worth it for a slightly faster /admin. However that requires an API change, this patch doesn't, and there's four weeks to code freeze without even a suggested fix there.

Additionally, toolbar.module populates the top level links with it's own toolbar_get_menu_tree() function which pulls out the top level items under /admin then lops off their children. This could probably be improved by doing something like adding a $depth parameter to http://api.drupal.org/api/function/menu_tree_all_data/7 - which would allow it to only check access for the top level items before returning $tree instead of all of them. However, without the caching to system_admin_menu_block() this'd be a waste of time, since the top level has to check access to all children due to the _access() function anyway. I opened #509584: APi fixes for menu_tree_data() including depth param a while back to clean that up, but that was before I noticed how much damage it was causing (rather than just being a bit messy).

Status:Needs work» Needs review
StatusFileSize
new3.4 KB
Failed: Failed to apply patch.
[ View ]

Fixed syntax error.

StatusFileSize
new4.9 KB
Failed: Failed to apply patch.
[ View ]

Added hook_cache_clear_all() to avoid system and/or toolbar.module having to register a submit handler on the permissons page just to flush it's own cache, that whole thing really needs a cleanup having module_exists('block') in cache.inc, but I don't want to add a dependency here on #496248: Refactor cache API which should hopefully clean it up a lot better.

toolbar.module also piggybacks on the system.module provided cid prefix to avoid having to duplicate a lot of code in both places.

@catch: good summary in #10. #296693: Hide empty admin categories did indeed bring on some interesting side effects.

StatusFileSize
new8.03 KB
Failed: Invalid PHP syntax in modules/system/system.module.
[ View ]

Not keen on the cache.inc change, so adding the glaringly missing hooks for user role insert/update/delete instead. Yes, this is scope creep, that's what happens when patches get committed that introduce loads of critical bugs instead of being dealt with properly before they're in, see http://drupal.org/node/484820#comment-1772926

Status:Needs review» Needs work

The last submitted patch failed testing.

The toolbar patch introduced a critical performance bug that is non trivial to fix. I seriously recommend rolling back the toolbar patch (if possible). One precedent for this is #310467: Slimmer hook_theme() which was rolled back because it broke the installer.

Status:Needs work» Needs review
StatusFileSize
new8.03 KB
Failed: Invalid PHP syntax in modules/user/user.admin.inc.
[ View ]

minus very strange typo.

Status:Needs review» Needs work

The last submitted patch failed testing.

Status:Needs work» Needs review
StatusFileSize
new8.03 KB
Failed: Failed to apply patch.
[ View ]

grr.

I see the approach, but I'm not sure I agree that just caching is the right approach vs. some simple API cleanups.

StatusFileSize
new1.34 KB
Failed: Failed to apply patch.
[ View ]

This function is written really badly: http://api.drupal.org/api/function/toolbar_get_menu_tree/7

I think the fairly simple change in this patch will already make for a dramatic reduction in access calls, by loading only the subtree we care about rather than the entire menu. There is a critical bug anyhow, since we could (based only current code) load any number of 'admin' links since ther is no check on the module attribute. I'll go visit #509584: APi fixes for menu_tree_data() including depth param too, since that should be fixed too.

I'm not sure the caching is correct or even doable (hence why we don't have it in the rest of the menu system), since there is no reason that access callbacks have to be strictly role based.

Status:Needs review» Reviewed & tested by the community
StatusFileSize
new350.61 KB
new347.23 KB

This cuts out half the extraneous calls to _menu_check_access() - after it's in we'll still need to fix system_admin_menu_block_access() for the rest.

Status:Reviewed & tested by the community» Needs review

Could we quickly get some benchmark data to prove that performing an extra query here we weren't doing before is a smaller performance hit than calling the function that many times? From what I understand, leaving PHP and going to the DB is monumentally slower than calling PHP functions.

Otherwise, this patch seems fine.

@webchick - since access callbacks may, e.g., load Views or cached data in a real-world scenario, I think this is a reasonable trade-off. However, we could probably hone this further if we care, e.g. by saving as a variable the menu link of interest so that we don't have to go to the DB on most page loads.

Status:Needs review» Reviewed & tested by the community

@webchick, I was going to do benchmarks, but then I ran into #529314: Toolbar throws errors for anonymous users which is sufficiently broken that benchmarks won't be great (i.e. we have to log to watchdog every request which will completely mess up trying to measure the impact of a couple of SELECTs).

However, looking at devel query log, this patch actually causes four less queries on the default front page

HEAD:
Executed 46 queries

Patch:
Executed 42 queries

Looks like we're doing one call to menu_load() instead of six (-5) plus the extra query here (+1) = -4.

Also see this webgrind screenshots I posted in #3 for the current performance impact of the toolbar - menu_tree_check_access taking up 70%, compared to 10% when the whole toolbar was cached, the reason the total adds up to more than 100% is because various function calls can be included within the count for other functions (theme() for example), so not an ideal measure, but rendering the entirety of /admin on every page and checking access for all the links twice isn't cheap.

StatusFileSize
new591.08 KB
new352 KB
new368.58 KB

Forgot screenshots:

devel query log output before/after patch.

Also a dpm(debug_backtrace()) inside menu_load() which shows it called by toolbar_get_menu_tree() vi menu access checks after about 12 levels of depth - because presumably one admin access callback is calling menu_load() for every menu.

if we finish #509584: APi fixes for menu_tree_data() including depth param, this will be radically improved, but in general access check can be pretty expensive, since each can load an object from the DB, so the patch here is almost always going to be a win despite the initial extra query.

Status:Reviewed & tested by the community» Fixed

Committed to HEAD.

Status:Fixed» Needs work

Hmm, actually I confused the behavior of function menu_tree_all_data() - this would make the code more correct, but should just wait anyhow for #509584: APi fixes for menu_tree_data() including depth param.

StatusFileSize
new1.04 KB
Failed: 13657 passes, 0 fails, 2 exceptions
[ View ]

anything left to do here? bot is not testing this patch since it is 'needs work'.

@moshe - I was waiting for this commit: #509584: APi fixes for menu_tree_data() including depth param, so we can now proceed. We need to think about whether we want the toolbar to be empty if the 'admin' link is moved to another menu, or whether we shoudl get the menu name from that link.

It would be nice to make function book_menu_subtree_data() a general menu API function - but the trick there is that we have to be able to define an extra table to join on mlid. I wanted to do this for all menu link functions also like menu_tree_page_data(), but time got away from me unless we can call it API cleanup.

StatusFileSize
new1.01 KB
Passed: 14478 passes, 0 fails, 0 exceptions
[ View ]

Here's a patch using the depth - for some reason the other part of the code from the prior patch doesn't work.

Status:Needs work» Needs review
StatusFileSize
new1.18 KB
Passed: 14475 passes, 0 fails, 0 exceptions
[ View ]

I didn't test this patch, but I wanted to make sure that there are no colons after @todo :P

Status:Needs review» Reviewed & tested by the community

Yup, now using $depth param.

Title:Too many calls to _menu_check_access()Clean up toolbar menu code
Priority:Critical» Normal
Issue tags:-Performance+Quick fix

Changing status since this is no longer a performance patch (calls to _menu_check_access() are unchanged by the patch). However still RTBC and very straightforward.

Created the follow-up #618530: System module's "listing" pages (and blocks) should use menu_build_tree() that is required to eliminate the nightmare-ish workarounds that are hacked into Toolbar module here.

This patch should still go in before that.

Additionally, #296693: Hide empty admin categories solves the "grouping item" access issue.

Status:Reviewed & tested by the community» Fixed

Committed to CVS HEAD. Thanks!

Status:Fixed» Closed (fixed)
Issue tags:-Quick fix

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