No-op and slow queries during menu rebuild

I am not seeing a decrease in queries.

Code comments would be useful. ;-)

I'll do a deeper review after chx chimed in as requested above.

This saved 150 queries for me on admin/build/modules. I tested with D6 since devel can't do query counting yet on D7. If the menu tests pass, this is ready to commit .code looks good.

I am experiencing horrible delays with 6.5 on admin/build/modules. On the same machine, 5.x runs like a champ.

I tried this patch. It helped to reduce queries from (the italic shows the actual output from devel log)
Executed 1747 queries in 24377.09 milliseconds.
to
Executed 1639 queries in 36639.19 milliseconds. Queries taking longer than 100 ms and queries executed more than once, are highlighted.
ms # where query
ms # where query
516.39 1 menu_link_save UPDATE menu_links SET menu_name = 'navigation', plid = 18, link_path = 'admin/settings/logging', router_path = 'admin/settings/logging', hidden = 0, external = 0, has_children = 1, expanded = 0, weight = 0, depth = 3, p1 = 2, p2 = 18, p3 = 37, p4 = 0, p5 = 0, p6 = 0, p7 = 0, p8 = 0, p9 = 0, module = 'system', link_title = 'Logging and alerts', options = 'a:1:{s:10:\"attributes\";a:1:{s:5:\"title\";s:156:\"Settings for logging and alerts modules. Various modules can route Drupal\'s system events to different destination, such as syslog, database, email, ...etc.\";}}', customized = 0 WHERE mlid = 37

Why do we have 1000+ queries on 6.x? On drupal 5.x, it only had 42 queries when I hit admin/build/modules. (Even with a fresh drupal 6 install, no modules enabled, it still generated 1000+ queries. see http://drupal.org/node/311626).

As you can see, I had to wait long time for the page to show up! Can someone throw some light on this problem? Is it mysql fine tuning issue? Why is it not a problem for 5.x on the same machines? I have attached my devel log. It looks horrible!

Another weird thing: even though queries came down, but page time actually went up :(

Tried again now that devel works on D7. Saved over 300 queries, many of them UPDATE queries. Code looks good.

Still some performance work to do on this page.

The number of queries on that page is crazy. I wonder if we can take advantage of the multi-insert feature of the new database abstraction layer to remedy this.

Is it a bit excessive that the entire menu is re-built whenever admin/build/modules is clicked? If I hit it twice in a row without updating anything, it still will rebuild everything. This is a heavy penalty.

I don't know if it's only rebuilding the menus. If it's true, then I wonder if there can be an option to allow user to choose when to rebuild (default can be true). At least, it gives user a choice (although a somewhat dangerous choice, since it may result in system being out of synch).

However, for the users who know they never touched the menu, they can choose not to rebuild.

Does this have to do with that famous $may_cache in hook_menu() of 5.x and earlier versions? Drupal 5.x doesn't have this problem at all.

I've committed this patch to CVS HEAD. Marking it 'code needs work' so we can backport it to D6 (and implement more improvements for D7).

Untested re-roll for D6.

Still saving 150 queries in d6 - no ill effects

I have a related problem I struggled with for months. My 6.x admin/build/modules takes forever to load. Many people experience similar problems. Many of them experience the problem on development platform only.

I have found my own solution, just want to share it here. I hope it can help other people as well.

See #22 in this post http://drupal.org/node/311626

Committed to 6.x. Fixed two code style issues:

- one too many space before || in menu_path_is_external($item['link_path']) || $item['link_path'] == '<front>'
- one too many dot in Don't bother with the query - mlid can never equal zero..

This caused the following issue in HEAD: #328110: Recoverable fatal error: Argument 3 passed to l() must be an array, because $item is passed by reference so you should return it with 'options' serialized. I'm pretty sure it will also happen in DRUPAL-6.

Rolled back for Drupal 6 pending a resolution of that bug. Patch updated with my whitespace changes attached for reference.

subscribing...

The patch itself is good, but depends on #328110: Recoverable fatal error: Argument 3 passed to l() must be an array being ported to D6.

Bumping to D7.

This doesn't looks nice:

  if (!$existing_item || array_diff_assoc($existing_item, $item)) {
    db_update('menu_links')
      ->fields(array(
        'menu_name' => $item['menu_name'],
        'plid' => $item['plid'],
        'link_path' => $item['link_path'],
        'router_path' => $item['router_path'],
        'hidden' => $item['hidden'],
        'external' => $item['external'],
        'has_children' => $item['has_children'],
        'expanded' => $item['expanded'],
        'weight' => $item['weight'],
        'depth' => $item['depth'],
        'p1' => $item['p1'],
        'p2' => $item['p2'],
        'p3' => $item['p3'],
        'p4' => $item['p4'],
        'p5' => $item['p5'],
        'p6' => $item['p6'],
        'p7' => $item['p7'],
        'p8' => $item['p8'],
        'p9' => $item['p9'],
        'module' => $item['module'],
        'link_title' => $item['link_title'],
        'options' => serialize($item['options']),
        'customized' => $item['customized'],
      ))
      ->condition('mlid', $item['mlid'])
      ->execute();
  }

We have made a array_diff_assoc() so we could just update the fields that actually changed and avoid sending huge unnecessary queries to the DB (plus the code will look nicer).

subscribing

(my 2cents ) Tested #27 patch on my -dev machine (Drupal 6.8, MySQL, Views, CCK and other module installed)

/admin/build/modules Devel results:

*With Patch*
Page execution time was 20235.63 ms. Executed 1592 queries in 1086.85 milliseconds.
Memory usage:
Memory used at: devel_init()=1.04 MB, devel_shutdown()=20.74 MB.

*Without Patch*
Page execution time was 20298.12 ms. Executed 1643 queries in 1101.98 milliseconds.
Memory usage:
Memory used at: devel_init()=1.04 MB, devel_shutdown()=20.76 MB.

Some time and queries reductions!
Regards

Re-Roll for latest D6.9 Release

I'm not up to date on the details of this issue, but just pointing out that for an eventual backport to D6, the following (in menu_link_save) is apparently needed as part of the patch:

   $existing_item = FALSE;
   if (isset($item['mlid'])) {
-    $existing_item = db_fetch_array(db_query("SELECT * FROM {menu_links} WHERE mlid = %d", $item['mlid']));
+    if ($existing_item = db_fetch_array(db_query("SELECT * FROM {menu_links} WHERE mlid = %d", $item['mlid']))) {
+      $existing_item['options'] = unserialize($existing_item['options']);
+    }
   }

(See the discussion at http://drupal.org/node/328110#comment-1175157)

What is the status of this patch? This issue has killed my dev site and is delaying a project. I don't want to have to nuke the install and start rebuilding the modules pool piece by piece.

I've set my php memory limit to 80M in .htaccess which seems to have worked around the issue but it takes a long time for the modules page to load in my Drupal6.9 install on a shared host.

My worry is that my host may throttle my memory usage back at some point, putting me back to square one.

Subscribing...

Hi guys, any love on a final D6 roll for this? I'm currently processing 6217 queries taking 117000ms to run anytime I access admin/build/modules, which in turn sometimes causes race conditions where drupal attempts to insert duplicate entries into menu_router, which generates 30 pages of watchdog logs.

A nice double-whammy I'd rather avoid. :/

Apollo610

#328110: Recoverable fatal error: Argument 3 passed to l() must be an array needs testing on Drupal 6 before this one can go in, so at the moment, efforts would be best spent getting that issue to RTBC.

Thanks for the redirect catch, I didn't realize there was a dependancy... I applied the D6 patch and am continuing development of my site w/ it installed, so I'll post my updates in the other thread.

Alrighty, looks like patch from #37's issue is ready to go in... any ideas on a timeframe for when we can test out this patch? I'm willing to use my dev site as one of the guinea pigs...

Not to be a PITA, but I just hate waiting 5 minutes everytime I have to access admin/build/modules when I need to remove or add something. During development this time adds up... :/

Thanks for everyone's work on this ...!

subscribe

subscribe

Dropping to minor. No-op queries like these may result in more DB round trips, but they are very fast queries and have little impact on overall infrastructure.

@David Strauss,
Perhaps the issue is a little larger than the no-op queries themselves. A number of us transfered to this issue because the modules page takes several minutes to load on some configurations. We're talking thousands of queries many of them taking over 500 milliseconds each.

Here is an example of a few:

660.67 _menu_router_build
579.91 _menu_router_build
530.8 _menu_router_build
443.78 _menu_router_build
401 _menu_router_build

Damien Tournoud marked http://drupal.org/node/311626 a duplicate. If it isn't a duplicate then the old issue needs to be reopened, and if this issue is really dealing with the same thing then this is by no means a minor issue. These ultra slow queries don't show up on every configuration and no one has found an absolute pattern for what's causing the page to load slowly. For example on my local test server the modules page crawls, on shared hosting online it is almost as fast as the Drupal 5 modules page. People have reported this issue with a very wide range of systems from Debian to Wamp.

I'll accept that this is "normal" priority now, but I'm renaming it.

Hi guys - Are we anywhere closer to a testable D6 patch for this issue?

Don't know about others, but I'm clocking a solid 4+ minutes to enable/disable modules at this point. Needless to say, testing out and uninstalling modules is not a very fun process right now.

I'm boosting this to critical. I don't think we understand the problem. I think there is a race condition or some excessive file scanning or something else going on. I've had timeouts on this page on an idle duo core 4GB webserver talking to an idle quad core 8GB database server.

subscribing

Short recap:
A version of this patch has been committed to D7: http://drupal.org/node/302638#comment-1067000
It was then committed to D6 and rolled back due to a dependency on #328110: Recoverable fatal error: Argument 3 passed to l() must be an array
http://drupal.org/node/302638#comment-1175161 suggests that the patch needs more work for D7
http://drupal.org/node/302638#comment-1209466 suggests that the patch needs work for D6

subscribing

subscribing

subscribing

I'm pretty sure this is affecting my site as well. Any thoughts on what we can do to work around it until the D6 patch is ready?

Not the solution to this problem, but this could also be causing your problem when you are using Organic Groups:
http://drupal.org/node/311626

Just a strange observation. I just upgraded my php from 5.1 to 5.2.9 and I am starting to see the same problem? My modules admin page loads were quite a bit faster before this upgrade. Don't know if this is anyway related to the problem?

@chipk1:

Just a strange observation. I just upgraded my php from 5.1 to 5.2.9 and I am starting to see the same problem?

Any chance you could change this from "observation" to "benchmark"?

Just another data point here. I was running MySQL 4.1 which is rather old. I upgraded to 5.1.32, but the problem persists. I have been on PHP 5.2.8 the entire time (before and after the problem came up.)

The whole admin interface is completely unusable. If I let it spin for 5 or more minutes I can get a page to load, but obviously that's not a workable solution.

Does anyone have any idea what triggers this problem? I'm open to anything at this point including hacking core files, experimental patches, or what not.

People experiencing problems with slow queries on the admin/build/modules page may wish to check my post here for a possible solution.

subscribing. i actually followed this thread, and i'm encountering the same problem with a nice fat site i'm working on.

I've also got this problem on two separate sites on separate servers. It just developed for each of the sites independently. What can be done to hasten the release of 6.x patch that will fix my 6.10 sites? One of the affected sites is a production site (i just updated to d6 last week!) and now its taking 2+ minutes to load admin/build/modules. I
need to resolve this ASAP - does that mean I must revert to my 5.16 snapshot of the site? Its not feesible to wait 2+ minutes every time i need to do some admin task - even if the public side of the site is working fine.

Thanks for any help or advice.
Andrew

subscribing

I am also encountering this issue.

subscribing

Honestly, the patches you published do not look that promising, if there is still around 90% of the queries remaining.

On my local test site I have:

modules page:
- Page execution time 99236.9 millis.
- 6471 queries in 91952.39 millis

admin_menu/flush-cache/menu:
- Page execution time 84088 millis
- 3128 queries in 81212 millis

admin/build/views/edit/* (saving a view)
- Page execution time 91309 millis
- 4004 queries in 87487 millis

Queries:
- cache_set: INSERT INTO cache_views (...)
- dblog_watchdog: INSERT INTO watchdog (...) - a lot of them, each around 90 millis
- _menu_router_build: INSERT INTO menu_router (...) - many many many, each around 90 millis, but I have also seen 1000 millis for one.
- a lot of other queries that need 0.x millis each, and thus don't seriously slow it down.

Typical menu_router query taking around 90 millis:

INSERT INTO menu_router (
  path,
  load_functions,
  to_arg_functions,
  access_callback,
  access_arguments,
  page_callback,
  page_arguments,
  fit,
  number_parts,
  tab_parent,
  tab_root,
  title,
  title_callback,
  title_arguments,
  type,
  block_callback,
  description,
  position,
  weight,
  file
) VALUES (
  'admin/content/node-type/*/fields/field_*',
  '',
  '',
  'user_access',
  'a:1:{i:0;s:24:\"administer content types\";}',
  'drupal_get_form',
  'a:3:{i:0;s:23:\"content_field_edit_form\";i:1;s:19:\"*\";i:2;s:18:\"field_*\";}',
  63,
  6,
  'admin/content/node-type/*/fields',
  'admin/content/node-type/*',
  '*',
  't',
  '',
  128,
  '',
  '',
  '',
  0,
  'modules/cck/includes/content.admin.inc'
)

So, I think we have the following problems to look into:
- Menu rebuild is called in some situations where it would not be necessary at all.
- Full menu rebuild, where a partial menu rebuild would do the job.
- Full menu rebuild needs many queries (maybe that is necessary)
- Most important: Each single 'INSERT INTO menu_router' query takes a lot of time. I really don't know why, it doesn't look like an overly complicated query.

We will win a lot if we can speed up the single menu_router INSERT queries. This makes a lot more sense than trying to reduce the number of queries by some 10%.

Maybe we could also combine a bunch of INSERT queries in one call.

Solution: MYISAM.

I switched the menu_router table to MYISAM, and the INSERT INTO query time dropped from ~90 milliseconds to ~0.4 milliseconds.
I would call this a success.

I suggest MYISAM for the following tables:
- menu_router
- cache_views
- cache_menu
- cache
- accesslog
- sessions (not sure about that one)
- performance_detail
- performance_summary
- variable (not sure about that one)
EDIT: I notice that this list is quite pointless..

It could be that in some situations MYISAM has other disadvantages over INNODB. Therefore I suggested to only convert those tables where a lot of writing needs to happen.

I guess that with a proper configuration the INNODB tables can be speed up as well, I just don't know how. The following might be interesting: http://drupal.org/node/311626#comment-1425596

I really think this is the direction to dig into. In an ideal world, the person using Drupal should not have to worry about such a thing, or at least get an advice how to speed things up.

That being said, there is still a lot of identical SELECT queries executed multiple times (as already mentioned by someone else). So, that would be the second point to look into.

The myisam "solution" doesn't help anyone using Postgres (like me), and will likely not hold up when your site is actually in use due to how myisam handles concurrency (or rather, doesn't).

My suspicion is that somewhere the menu is being rebuilt when the menu is rebuilt when the menu is rebuilt when the menu is rebuilt....

I think this issue is hurting me on admin/build/modules as well. From looking at mytop, it looks like even the SELECT queries can get bogged down during a menu_rebuild. Maybe when (if?) #251792: Implement a locking framework for long operations gets into 6.x, this might not be as much of an issue...

I really don't see the need for the ridiculously high number of queries happening during one menu_rebuild.

I propose to rewrite the menu_rebuild function, see
Rewrite the function menu_rebuild

Basic idea:
- One big query to load the menu_links and menu_router tables into php arrays.
- Do some computations.
- Write the changes to the DB, if any.

EDIT:
The less basic idea is:
- Scan all implementations of hook_menu.
- Look into menu_router table, to see which lines we have to insert, update or delete. This can be done with one big SELECT query.
- Execute the necessary INSERT, UPDATE and DELETE queries.
- Scan menu_links for necessary changes, based on the new contents of menu_router (that we have in memory at this point).
- Write the changes to menu_links

I'm still getting a large number of these WHERE mlid = 0 queries on D6 when I do a menu_rebuild() (around 1300). I don't understand why they should happen at all. Won't mlid always be greater than 0?

I just read robertDouglass' recap in #49 and it says that the patch was committed to D6 and then rolled back due to a dependency on #328110: Recoverable fatal error: Argument 3 passed to l() must be an array. That issue has been resolved in 6.x now, so can the patch be committed to D6 again? I just added if (isset($item['plid']) && $item['plid'] != 0) back to my menu.inc and it seems to have eliminated the WHERE mlid = 0 queries, at least.

Actually, never mind. It looks like the number of queries is significantly less when it's simply if (isset($item['plid'])) {. Something else must be going on here.

I want to add another wrinkle to the discussion. On my local dev environment, it takes almost as long for drush to scope out the commands modules add. Running the drush command to get a list of available commands is taking an astonishing amount of time to finish.

+++ menu.inc	13 Jan 2009 18:05:21 -0000
@@ -1864,7 +1864,13 @@
   if (isset($item['plid'])) {
-    $parent = db_fetch_array(db_query("SELECT * FROM {menu_links} WHERE mlid = %d", $item['plid']));
+    if ($item['plid']) {
+      $parent = db_fetch_array(db_query("SELECT * FROM {menu_links} WHERE mlid = %d", $item['plid']));
+    }
+    else {
+      // Don't bother with the query - mlid can never equal zero.
+      $parent = FALSE;
+    }
   }

This part needs to be reverted (which is dealt with in #550254: Menu links are sometimes not properly re-parented).

Beer-o-mania starts in 15 days! Don't drink and patch.

For PostgreSQL users putting menu_rebuild() in a transaction makes a huge difference. This is probably because the database will sync to disk on every update under normal circumstances. Using a transaction will only require a single sync at the end. MySQL should have no problems with these additions.

As far as I can see the only two issues here are:

http://drupal.org/node/302638#comment-1175161

and

http://drupal.org/node/302638#comment-1930784

#76 has an existing patch elsewhere. I've opened #693344: Clean up menu_link_save() to not update identical fields for the other issue. The original patches here were committed, others have been committed elsewhere. If there are specific followups to be done, please open new issues since this has become bogged down in meta-discussion and is impossible to follow.