Latest tweaks to bootstrap.inc can make Drupal sluggish when there is code that tries to load a file that doesn't exist

Confirm, same problem.

Confirm, same problem.

Added link to related issue.

I cannot reproduce the problem, can you give steps?

I have a situation where an empty string is passed as parameter $name, which causes some extra loops for no reason.
See a proposed fix here https://www.drupal.org/node/2383823#comment-9385897

Here's a patch to at least put a warning in watchdog when it can't find a file in the db (and thus executes a full recursive file scan). Since 7.33 a missing file might be a performance killer for your site.

See my blog post (http://www.vdmi.nl/blog/i-went-drupal-733-and-all-i-got-was-slow-site) and some discussion in #2228825 for more information.

I tested the patch in #8 and it indeed found some things I need to look into.

Changing the issue to 7.x-dev as that is where the patch will be applied.

+++ b/includes/bootstrap.inc
@@ -864,6 +864,9 @@ function drupal_get_filename($type, $name, $filename = NULL) {
+          watchdog('bootstrap', 'Bootstrap could not locate file @name of type @type in the database.', array('@name' => $name, '@type' => $type), WATCHDOG_WARNING);

Could we "quote" the values so they don't run in the sentance and maybe include the $file variable for more context?

Bootstrap could not locate file formtips of type theme in the database.

nm #10 about the $file because it's empty all the time "", but quoting the values would help.

I noticed that in my screenshot all those cases are due to omega's excludes in my theme info file:

settings[omega_css_exclude][] = field_group/horizontal-tabs/horizontal-tabs.css
settings[omega_css_exclude][] = workbench/css/workbench.block.css
settings[omega_css_exclude][] = workbench_moderation/css/workbench_moderation.css
settings[omega_css_exclude][] = panels/css/panels.css
settings[omega_css_exclude][] = commerce_ajax_cart/css/commerce_ajax_cart.css
settings[omega_css_exclude][] = addtoany/addtoany.css
settings[omega_css_exclude][] = formtips/formtips.css
settings[omega_js_exclude][] = formtips/formtips.js

Moving those to standard hook_css_alter() and hook_js_alter() with unset()s seemed to help that out.

Really rough xhprof before and after diff:

Also note that this sluggish feeling seems to be only after a page cache clear and those watchdog warnings won't show up (for me anyway) without clearing the page cache. So both runs were after a page flush cache.

I'll change the patch to include quotes later (or maybe to 'Bootstrap could not locate file "@name.@type" in the database.'?), but maybe we should think of some better solution here?

The sluggish feeling only after cache clear is probably because it caches the result.
When you use module_load_include, it doesn't cache the result, so it's sluggish on every request (and even killing when it's a site with much traffic).

Maybe we can setup a patch to profile and prove the slowness.

A few broken paths to files. One patch with and without the change from the previously issue.

Then we can run xhprof kit on them both.

@see https://www.drupal.org/contributor-tasks/profiling

Now I'm really curious how modifying a module's css/js has anything to do with loading the module...

Oh because I'm calling drupal_get_path('module', 'field_group') in the css alter hook...

Please Ignore my crazy talk in #15 and #16. It's true I think just a bit unrelated to the task at hand.

I think this issue it related and could have the fix for the problem
https://www.drupal.org/node/1081266#comment-6874620

The concept is to cache the data, avoiding re-doing the job more than once.

It also outputs a message when a module is not found.

This issue is 2 years old and I think it is time to see if we can get it committed.

I'm adding a note about this to the 7.33 release notes.

I found this via the release notes so thanks for that. I'm testing now in a test environment and I'm seeing the full file system scan being triggered for orphan module records in the system table.
deleting the orphan records prevents the log messages (and performance problem) but is that safe? The first couple I found were custom modules we've developed (and since removed), but then I found commerce_coupon_ui which is apparently left over from Commerce Coupons 1.x. Is it safe to delete records from that table if the module doesn't exist in the filessytem and does anyone know why they would still be there?
delete from system where name in ('commerce_coupon_ui');

Does anyone know if this is because of some quirk in my site's history, or is orphaned records a known issue? Thanks.

@pandaPowder The orphaned records you are seeing are probably there because you forgot to disable the module (you may have just removed the files from your site.) If you put back commerce_coupon_ui, disable it (and uninstall for good measure) then the problem should be resolved.

If commerce_coupon_ui is part of commerce_coupon and you are still using it, I would open an issue in that queue referencing this problem. Perhaps all that's needed is an update or uninstall hook :)

Adding patch for resetting to how it was before, for those of us who prefer to avoid the regression until a true fix is added.

@lorique
See: https://www.drupal.org/node/1081266#comment-9411015 for a D7 patch

@jeroen.b

Yeah i saw it, and prefer to reset to the old ways until its reviewed and tested by smarter people than I, and put into core. This is purely because the site was working fine with it before, so it can continue to until a sure fix is in.

+        else {
+          watchdog('bootstrap', 'Bootstrap could not locate file @name of type @type in the database.', array('@name' => $name, '@type' => $type), WATCHDOG_WARNING);
+        }

I said something similar at #1081266-204: Avoid re-scanning module directory when a filename or a module is missing but maybe trigger_error() is better than watchdog() here. It would get the message into watchdog too, but also would display it on the screen on dev sites which would be a good thing for a bug like this.

How about?

<?php
if ($file === FALSE) {
  // watchdog
  // add to files array
} else if (file_exists(…)) {
  // add to files array
}
?>

In that way we keep the old (fast) logic, recognize the strangeness, complain to the log, and skip the bogus file exists check.

Is there anything left to do in this issue now that #1081266: Avoid re-scanning module directory when a filename or a module is missing is fixed?

The patch in #8 (to flag missing files in watchdog) no longer applies cleanly to 7.50, and I suppose since #1081266 is now fixed this one is now resolved anyway?

Yes, lets close this one as a duplicate.