Problem/Motivation

To avoid performance deficit when multiple modules are missing. The deficit occurs because the "modules" directory is rescanned perpetually to look for missing modules on certain pages, such as admin/config.

Proposed resolution

The solutions is to cache the result of the scanning of the "modules" directory in a static variable.

Remaining tasks

None.

User interface changes

None.

API changes

None.

Original report by mfb

This patch provides a performance boost for sites that are missing modules (common on old sites which have been maintained for many years). In this case, drupal_system_listing() and file_scan_directory() will be called over and over looking for missing modules on certain pages, such as admin/config.

This patch adds an additional static variable to drupal_get_filename() to store an array of mask-directory combinations that have been scanned. Once one scan has been performed for a particular extension in a particular directory, there is no need to run the same scan later in the same request.

Files: 
CommentFileSizeAuthor
#189 drupal-1081266-189-avoid-rescanning-missing-module-D7.patch3.31 KBjeroen.b
PASSED: [[SimpleTest]]: [MySQL] 41,135 pass(es).
[ View ]
#186 drupal-1081266-186-avoid-rescanning-missing-module-D8.patch5.44 KBjeroen.b
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 87,309 pass(es).
[ View ]
#181 includes_menu_inc.png225.58 KBjoelpittet
#173 bootstrap_inc_-.png198.21 KBjoelpittet
#171 drupal-1081266-171-drupal_get_filename-extra-debug-do-not-test-D7.patch1.87 KBjeroen.b
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Unable to apply patch drupal-1081266-171-drupal_get_filename-extra-debug-do-not-test-D7.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]
#162 drupal-1081266-162-avoid-rescanning-missing-module-D8.patch3.78 KBjeroen.b
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 84,136 pass(es).
[ View ]
#159 drupal-1081266-159-avoid-rescanning-missing-module-D8.patch3.76 KBmikeytown2
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 82,539 pass(es).
[ View ]
#157 drupal-1081266-157-avoid-rescanning-missing-module-D8.patch3.76 KBmikeytown2
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/includes/bootstrap.inc.
[ View ]
#155 drupal-1081266-155-avoid-rescanning-missing-module-D8.patch3.75 KBmikeytown2
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/includes/bootstrap.inc.
[ View ]
#150 drupal-1081266-137-avoid-rescanning-missing-module-D8.patch5.39 KBmarcelovani
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 82,441 pass(es).
[ View ]
#138 drupal-1081266-138-drupal_get_filename-D7.patch1.8 KBjeroen.b
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Unable to apply patch drupal-1081266-138-drupal_get_filename-D7.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]
#137 drupal-1081266-137-avoid-rescanning-missing-module-D8.patch5.39 KBjeroen.b
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 82,039 pass(es).
[ View ]
#132 drupal-1081266-132-avoid-rescanning-missing-module-D8.patch5.54 KBmikeytown2
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 82,037 pass(es).
[ View ]
#127 drupal-1081266-127-avoid-rescanning-missing-module-D8.patch5.32 KBmikeytown2
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 81,994 pass(es).
[ View ]
#124 drupal-1081266-124-avoid-rescanning-missing-module-D8.patch4.12 KBmikeytown2
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 81,957 pass(es), 1 fail(s), and 0 exception(s).
[ View ]
#120 avoid_rescanning_drupal_get_filename-1081266-120.patch2.89 KBjeroen.b
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 81,956 pass(es), 2 fail(s), and 1 exception(s).
[ View ]
#102 drupal-1081266-102-drupal_get_filename-D7.patch1.75 KBmikeytown2
PASSED: [[SimpleTest]]: [MySQL] 39,617 pass(es).
[ View ]
#95 drupal_get_filename_cache-1081266-95.patch7.09 KBtsphethean
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch drupal_get_filename_cache-1081266-95.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]
#93 drupal_get_filename_cache-1081266-93.patch7.09 KBtsphethean
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch drupal_get_filename_cache-1081266-93.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]
#80 drupal_get_filename_cache-1081266-80.patch7.24 KBtsphethean
Test request sent.
Previous result: FAILED: [[SimpleTest]]: [MySQL] 40,161 pass(es), 97 fail(s), and 82 exception(s).
[ View ]
#74 drupal_get_filename_cache-1081266-74.patch7.09 KBtsphethean
FAILED: [[SimpleTest]]: [MySQL] 40,038 pass(es), 97 fail(s), and 82 exception(s).
[ View ]
#69 drupal_get_filename_cache-1081266-69.patch7.1 KBtsphethean
FAILED: [[SimpleTest]]: [MySQL] Failed to run tests: PHP Fatal error encountered during run_tests.sh. See review log for details..
[ View ]
#64 drupal-1081266-64-drupal_get_filename-D8.patch1.78 KBmikeytown2
PASSED: [[SimpleTest]]: [MySQL] 36,983 pass(es).
[ View ]
#62 drupal-1081266-62-drupal_get_filename-D8.patch1.79 KBmikeytown2
FAILED: [[SimpleTest]]: [MySQL] 36,999 pass(es), 0 fail(s), and 130 exception(s).
[ View ]
#60 drupal-1081266-60-drupal_get_filename-D8.patch1.77 KBmikeytown2
FAILED: [[SimpleTest]]: [MySQL] Drupal installation failed.
[ View ]
#58 drupal-1081266-58-drupal_get_filename-D7.patch1.75 KBmikeytown2
PASSED: [[SimpleTest]]: [MySQL] 39,062 pass(es).
[ View ]
#30 image1-7.8-default.png54.12 KBKars-T
#30 Image2-7.8-patch_from_1081266.png43.2 KBKars-T
#30 Image3-7.8_patch_from_1081266_and_733308.png35.19 KBKars-T
#30 Image4-7.8_patch_from_733308.png40.7 KBKars-T
#24 2011-10-01_025602.png7.66 KBxandeadx
#9 1081266-drupal_get_filename.patch1.99 KBmfb
PASSED: [[SimpleTest]]: [MySQL] 29,486 pass(es).
[ View ]
#4 1081266-drupal_get_filename-D7.patch2.37 KBmfb
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 1081266-drupal_get_filename-D7.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]
drupal_get_filename.patch1.99 KBmfb
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch drupal_get_filename_4.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]

Comments

catch’s picture

I can't remember which issue this came up in, (edit: now I can, it was #752730: Remove file_exists() during bootstrap) but someone moshe mentioned we should probably disable modules that are missing if we find they don't exist. Old core modules like ping that were removed, contrib modules that are deleted rather than uninstalled, there are lots of ways this happens.

If we did that, are there still circumstances this could run more than once? Also even if we do go for disabling those, I'm split on whether it should be a one-off or built in somewhere.

mfb’s picture

Disabling modules would not address this issue. system_status() calls drupal_load_updates() which calls drupal_get_installed_schema_version() which loads everything of type module from the system table, regardless of status. module_load_install() is called as long as the schema version is 0 or higher, even if the module is disabled.

sun’s picture

Status:Needs review» Needs work
+++ includes/bootstrap.inc
@@ -702,16 +702,19 @@ function drupal_get_filename($type, $name, $filename = NULL) {
+      if (!isset($scanned[$extension][$dir])) {
...
+        $scanned[$extension][$dir] = TRUE;

1) Let's move the variable assignment right below the conditional check, so the purpose of the conditional as well as the assignment is clear.

2) Wouldn't it make more sense to flip $dir and $extension in the array? And when considering that, wouldn't $dirs be a better name than $scanned? Perhaps not, just an idea.

Powered by Dreditor.

mfb’s picture

Status:Needs work» Needs review
StatusFileSize
new2.37 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 1081266-drupal_get_filename-D7.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]

OK changed to $dirs and moved that line (hope $dirs variable is ok coding standards wise).

sun’s picture

My brain is filled up with other stuff right now, so just throwing the idea out there: Any remotely potential issues if $dir == $extension (say, 'inc') ?

Also, we should open a separate issue to fix the root cause; namely, fixing {system}.status columns on a certain page/callback.

sun’s picture

mfb’s picture

$dir should be one of themes, themes/engines, modules, profiles and $extension should be one of info, engine, module, profile. But I don't think there'd be any problem if $dir == $extension.

As mentioned in #2, this code is running for all modules, disabled and enabled, so disabling missing modules wouldn't help here.

Damien Tournoud’s picture

Version:7.x-dev» 8.x-dev
Issue tags:+needs backport to D7
mfb’s picture

StatusFileSize
new1.99 KB
PASSED: [[SimpleTest]]: [MySQL] 29,486 pass(es).
[ View ]

Here's the D8 version.

Peter Bex’s picture

+1 on this patch, this can really slow down some sites!

mfb’s picture

hopefully "+1" means you reviewed the patch? it's not totally clear :)

Peter Bex’s picture

No, I just wanted this bug to get fixed. Didn't get around to testing it. Sorry :)

das-peter’s picture

Could this issue be related to this one #733308: Add static caching for drupal_system_listing()?

mfb’s picture

Related, but this is a higher-level fix to add (more) static caching to drupal_get_filename() so as to avoid unnecessary calls to drupal_system_listing() altogether.

Mark Theunissen’s picture

I've tested the patch and it works - the speed increase is major for my upgraded site that has 17 orphaned module entries in system table (I will be removing those).

The patch provides a working solution, but I wonder if it would be better to implement #733308: Add static caching for drupal_system_listing() as that adds a static cache to drupal_system_listing(), which will catch other places this may crop up. Once that is in place, I think the performance increase by doing this high level fix will be quite small.

mfb’s picture

Hmm #733308: Add static caching for drupal_system_listing() seems like redundant static caching of a large array, when drupal_get_filename() already has a static cache of $files found via drupal_system_listing()?

corbacho’s picture

I think this bug is more important than it seems.

I had only 1 orphaned module in a brand new Drupal 7 site we are building. (It was a feature-module that was removed from our git repository without proper uninstall)
I discover this bug only because I was profiling it, so I can give you some real data:

BEFORE:
The frontpage load taking 20 secs.
"file_scan_directory" was executed 1162 times. Taking 9 seconds in total
*Every single* page load.

AFTER:
Frontpage load taking 7 secs.
'file_scan_directory' wasn't executed at all.

(The load times are quite increased because of the profiler tool. Without profiling, it takes about half of the time in both cases)

So, especially if you have a lot of folders it's really expensive. In my case was even worse because I placed CKEditor source code folder inside the module folder. It has 238 folders. I have put it now in /libraries/ instead. (This reduced file_scan_directory to 868 calls, 7 secs in total)

But I think it's quite easy to end up in this situation and very difficult to realize for normal users, unless you have PHP debugging tools.

corbacho’s picture

That dramatic change of speed was due of my own debug patch:
If ($name == orphaned module) return;

But with the patch of #4 still file_scan_directory is called 434 times taking 4 secs.
The problem is that those 4 secs are in *every* single page load.

mfb’s picture

You might want to figure out why the scan is happening on every page load. Theoretically it should only happen on certain paths, such as admin/config which calls system_status().

tbenice’s picture

sub

anavarre’s picture

Subscribe

MaxWesten’s picture

#4 is a drastic speed improvement.

Kars-T’s picture

Subscribe. This is really needed. The Problem killed 80% performance of 2 our D7 sites.

xandeadx’s picture

StatusFileSize
new7.66 KB

subscr

Kars-T’s picture

Status:Needs review» Reviewed & tested by the community

I did test and profile this on a major site of ours. The bug killed the performance and every page call did use 100% CPU power and took around 30 seconds. With suns query fix from #1096742: Disable enabled but missing modules everything runs fine again CPU usage is very low again. But still file_scan_directory eats up 16% of a page-call. With this patch it goes down to 9%. Still a lot but much nicer and there shouldn't be any endless recursion because the directories are scanned over and over again .

The patch itself is very simple. Just one more static variable. And than a check if the directory was already parsed so it is not checked again for this page-call. I say RTBC.

das-peter’s picture

+1 for getting this in asap. We use this patches (this one too: #733308: Add static caching for drupal_system_listing()) in production, too. And everything works like a charm.

webchick’s picture

Assigned:Unassigned» catch

Since this is a performance patch, and since catch already chimed in above, moving to his queue.

alanburke’s picture

Tested patch at #4
Worked and made a dramatic difference on a site.

catch’s picture

Status:Reviewed & tested by the community» Needs review
Issue tags:+Needs profiling

I'd like to see the following before committing this:

Profile a site where this bug is in effect, then compare:

No patch.

This patch.

This patch and #733308: Add static caching for drupal_system_listing().

#733308: Add static caching for drupal_system_listing() without this patch.

Screenshots from either xdebug or xhprof will do fine - can show detail from drupal_system_listing() or file_scan_directory() whichever is most obvious.

Kars-T’s picture

Status:Needs review» Reviewed & tested by the community
StatusFileSize
new40.7 KB
new35.19 KB
new43.2 KB
new54.12 KB

Sure I do this :)

Okay I did
drush dl devel feeds job_scheduler
drush en devel feeds feeds_ui job_scheduler -y

and than deleted those modules.

With latest 7.8 bootstrap the load of "/" takes around 20 seconds.
Default

With patch from 1081266#9 the load of "/" takes around 3 seconds.
Image2-7.8-patch_from_1081266

With patch from 1081266#9 and 733308#8 the load of "/" takes around 3 seconds.
image1-7.8-default

With patch from 733308#8 the load of "/" takes around 3 seconds.
Image4-7.8_patch_from_733308

Performance seems to be equal with any patch. But lowest usage of file_scan_directory() is with both. For D8 I'd say test peters a bit more and add it. BUt for D7 I would really love to see the patch from this issue in the next release. If you reorganise features your site will be dead in the current state.

catch’s picture

Status:Reviewed & tested by the community» Needs work

Thanks for the profiling, that means there's no reason to have both patches then.

#733308: Add static caching for drupal_system_listing() is the older issue but I've marked that duplicate.

However to me it makes more sense to add the static caching to either drupal_system_listing() or file_scan_directory() - since that's called by more places (such as the installer which was the original motivation for opening that issue).

mfb’s picture

@catch: since drupal_get_filename() already has a static cache of $files found via drupal_system_listing(), are you suggesting moving the static cache from drupal_get_filename() to drupal_system_listing()?

catch’s picture

@mfb, the drupal_get_filename() cache is primed by http://api.drupal.org/api/drupal/includes--module.inc/function/module_li... on every request, so removing the cache from there isn't an option. The way that cache is primed is a bit odd so we could consider trying to clean that up elsewhere.

Since drupal_system_listing() is only really called via this error condition or otherwise very rarely it seems fine to have the static cache in two places to me - in the usual case they won't both be used at the same time.

Kars-T’s picture

@catch So is this issue again RTBC or what should be done?

klausi’s picture

Priority:Normal» Critical
Status:Needs work» Needs review

Just ran into this myself, this a huge performance show stopper. Escalating to critical. Patch from #9 still applies. Marking for review.

Kars-T’s picture

Status:Needs review» Reviewed & tested by the community

Than again I set this to RTBC. But for D8 I would say it should follow the more complex path that das-peter showed in #733308: Add static caching for drupal_system_listing(). For D7 I say this is essential or any bigger system that uses features will die eventually. D7 really needs some kind of hot fix.

Dries’s picture

Priority:Critical» Normal
Status:Reviewed & tested by the community» Needs work

Committed to 7.x and 8.x. Thanks!

I'd still like to figure out why we keep looking for these files on every request. It feels like we patched the problem vs eliminated the root cause. I've updated the priority and status accordingly. Hopefully we can continue to investigate this.

das-peter’s picture

Thanks & I fully agree, working on this felt always like patching a symptom and not the cause.
While the static cache is a good thing anyway, I've been asking myself if it would be a good idea to disable missing modules and flag them as broken. Idea behind this is that I would like to know if there's anything wrong with my setup.
Next question would be what's considered as broken?
Only if the full module is missing or even if registered files of a module are missing?
What about a consistency check on the module page or an extra report page?

Kars-T’s picture

system_list() is called on every bootstrap. But there is only a cache for the database table. The directories will be scanned on every call.

So is there any reason why we couldn't put the result from the loop in line 185 into the cache?

Only thing I currently can think of we will have a problem if a module is gone missing.

flock’s picture

Version:8.x-dev» 7.x-dev

Druapl 7.9
Hi, i'm new to drupal and I believe I am suffering from poor performance because of this same reason.

on my site I keep getting Internal Server errors, not enough memory errors and My webhosting company tells me I have to upgrade to the $19.99 per month plan in stead of shared hosting [thanks greengeeks the super useful drupal hosts]

Also, images seem to drop off
Site Logo
Captcha Image
Views gallery - of small rotating logos
-this curiously only on Mac Safari and Mac Firefox

Can any one please instruct me or direct me as to how I can apply or where exactly do I execute that snippet of code so I can find out what modules are causing the super slow performance?.

This is the only post that I found that had a seeming relationship to my problem, my apologies if this is not the right place to post it.

Many Thanks

oriol_e9g’s picture

Version:7.x-dev» 8.x-dev

First we have to solve this in D8. The most important problem here was solved in D7 and commited in October.

I think that your problem is a suport request, open a new issue.

catch’s picture

Assigned:catch» Unassigned
bmateus’s picture

I've patched my bootstrap with patch #4 and the performance increase is notorious.
Any idea when this might be updated on a D7 official version?
I think it is very important, as most D7 sites I've built all suffer from the same lack of performance.

klausi’s picture

marloncastrillo’s picture

Priority:Normal» Major

Subscribe

Tor Arne Thune’s picture

bensnyder’s picture

Priority:Normal» Major
Tor Arne Thune’s picture

Priority:Major» Normal

Cross-post.

onelittleant’s picture

What would the negative implications be of just eradicating invalid system table entries? Perhaps provide an indication on the module / theme / status report admin screens indicating references to modules or themes that don't exist and providing a button to simply delete the references.

http://drupal.org/node/1052250#comment-5113888

onelittleant’s picture

Priority:Major» Normal

You can try this if the problem is related to system table references to modules that don't exist:

http://drupal.org/node/1052250#comment-5113888

emcniece’s picture

Pretty worried about this. I've followed all the links here, done all the patches to 10 different installations of D7 in different combinations, and the only conclusion I can draw is that I simply have too many modules installed.

Initially, page load times were upwards of 70 seconds and file_scan_directory() was being called over 10,800 times each page view. Since updating to 7.x-dev and monkeying around with reducing the number of available modules, I've got this down to ~1500 calls but the page load is still around 16 seconds.

If it helps anyone, I initialized a variable at the top of /includes/file.inc (outside any function, as a global):

<?php
 $ctest
= 0;
?>

and then threw at the bottom of file_scan_directory():

<?php
 
global $ctest; echo $ctest++. " $depth: $dir<br />\n";
?>

My site has 77 modules installed on top of core, with 37 available but not installed. Is this simply too complex for Drupal?

catch’s picture

You should do a debug_backtrace() from file_scan_directory() to see what's calling it. It shouldn't be called during normal operation at all, but it can be if you have a badly behaving contrib module installed.

I've seen sites with upwards of 300 modules installed, 100 is unfortunately not unusual at all.

emcniece’s picture

DUDE, catch... THANK YOU for the nudge!! I rolled down that path earlier but abandoned when I couldn't get any meaningful data out of debug_backtrace(). Well this time I found the right output - and here's the results:

  • drupal_bootstrap: 67 calls
  • menu_execute_active_handler: 1434 calls

Crazy. What does that even mean, rogue menus? I'm looking at menu_execute_active_handler right now.

For reference, here's what the last few lines of my file_scan_directory() now looks like:

<?php
    $bt
= debug_backtrace();
   
$end = end($bt);
   
var_dump($end);
    global
$ctest; echo $ctest++. " $depth: $dir\n";
  return
$files;
}
// end file_scan_directory()
?>

Any ideas by chance?

catch’s picture

You're looking at the first function in the backtrace, instead find file_scan_directory() in the full backtrace then work up from there - the first couple of functions you find outside file.inc are a good place to concentrate on.

emcniece’s picture

Dear catch: today I learned things.

  1. debug_backtrace() is super handy
  2. I need to be more careful about where I leave my drupal_flush_all_caches() calls
  3. 16 hour days suck
  4. the Drupal community is a godsend

For anyone else: drupal_flush_all_caches() slows sites down BIGTIME and seems to initiate a good number of file_scan_directory() calls through whatever cache-clearing things it does. This didn't really have much to do with the actual thread topic, but the directory scans instead turned up as a symptom. Thanks again for your help.

sertaconay’s picture

Status:Needs work» Needs review

drupal_get_filename.patch queued for re-testing.

ExTexan’s picture

When I went to apply this #9 patch (manually) in D7, I saw that the *new* code is already in the version of D7 I'm running (7.14), but I'm still experiencing very slow initial loading of my front page. This is running locally on a virtual host in Win7 with WAMP. After the initial load time of 15-20 seconds, my pages load within a second or two thereafter.

Anyone have any suggestions of what else to try / look for?

mikeytown2’s picture

Version:8.x-dev» 7.x-dev
StatusFileSize
new1.75 KB
PASSED: [[SimpleTest]]: [MySQL] 39,062 pass(es).
[ View ]

@sertaconay
There is no active patch above to review, Dries in #37 committed patches to D7 (#4) & D8 (#9).

I've attached a patch for 7.x that fixes this issue for us. Once testbot gives the A-OK, go ahead and move the issue back to 8.x.

DerekL’s picture

Wow.

The above patch just turned my glacial D7.14 ZWAMP dev env into a rocketship.

You all deserve beers, thanks.

mikeytown2’s picture

Version:7.x-dev» 8.x-dev
StatusFileSize
new1.77 KB
FAILED: [[SimpleTest]]: [MySQL] Drupal installation failed.
[ View ]

Patch for D8 that should fix this issue as well.

Status:Needs review» Needs work

The last submitted patch, drupal-1081266-60-drupal_get_filename-D8.patch, failed testing.

mikeytown2’s picture

Status:Needs work» Needs review
StatusFileSize
new1.79 KB
FAILED: [[SimpleTest]]: [MySQL] 36,999 pass(es), 0 fail(s), and 130 exception(s).
[ View ]

Using the D8 caching interface now :)

Status:Needs review» Needs work

The last submitted patch, drupal-1081266-62-drupal_get_filename-D8.patch, failed testing.

mikeytown2’s picture

StatusFileSize
new1.78 KB
PASSED: [[SimpleTest]]: [MySQL] 36,983 pass(es).
[ View ]

What happened to CACHE_TEMPORARY?
http://drupalcode.org/project/drupal.git/blob/58964deb124e55d61f51a167d5...

API says it's still in there: http://api.drupal.org/api/drupal/core!includes!bootstrap.inc/constant/CA... and is referenced here http://api.drupal.org/api/drupal/core!lib!Drupal!Core!Cache!CacheBackend...

Going to re-roll patch with -1 instead of CACHE_TEMPORARY as a temp solution to this problem.

mikeytown2’s picture

Status:Needs work» Needs review
aspilicious’s picture

#730060: Replace CACHE_TEMPORARY, cache_clear_all() and minimum cache lifetime with cache tags support

The api docs have troubles with new commits. It can take weeks before it gets refreshed.

mikeytown2’s picture

So I need to add in 'drupal_get_filename' to the list of caches getting reset in system_list_reset(), or is there a better way to do this?

tsphethean’s picture

I came across this issue when looking at why D6 was querying the DB on every module_load_include call and thinking of how to mitigate.

My understanding of the issue is that it fixes the edge case where the DB isn't available to lookup the module path (or its not specified in system table), and the module directory no longer exists

Is there a reason why even with the improved D7/8 drupal_get_filename doing file scans and then caching the list of bad files, why we wouldn't add the list of found files to a cache table for retrieval by future calls? I guess it would need profiling, and maybe be a configurable option depending on what caching mechanism was being used, but would looking up a value from a cache not be more efficient across requests? My thought is that on a production site the files aren't likely to change much in between requests, so the efficiency gains could be quite sizeable?

If this feels like getting off topic (or has been raised as another defect elsewhere) I'm happy to move it out of this issue and create a new one, and equally happy to attempt some work on a patch if it feels like a valid way of thinking.

tsphethean’s picture

StatusFileSize
new7.1 KB
FAILED: [[SimpleTest]]: [MySQL] Failed to run tests: PHP Fatal error encountered during run_tests.sh. See review log for details..
[ View ]

Ok, so I've had a go based on my comment in #68 and @mikeytown2's good work in #64 at creating a cache which stores the "good" cache entries, and an additional cache for the "bad" or missing files being included.

I need to do more profiling to determine if there is any performance benefit of this cache on a vanilla installation, and also with alternative cache backends, but thought it best to see what testbot and others think.

My working assumption is that retrieving from the cache should always be more optimal than a db query even when the cache is in the db, (flawed assumption?) but that the benefits of this would be felt in complex sites with 100+ modules, particularly custom modules, with dedicated caching solutions.

Status:Needs review» Needs work

The last submitted patch, drupal_get_filename_cache-1081266-69.patch, failed testing.

tsphethean’s picture

Hm. Not sure I quite understand this. Output from the test failure is:

Basic standard + all profile upgrade path, bare database 25 passes, 33 fails, and 39 exceptions

Fatal error: Cannot use object of type stdClass as array in /var/lib/drupaltestbot/sites/default/files/checkout/core/includes/bootstrap.inc on line 2901
FATAL Drupal\system\Tests\Upgrade\LanguageUpgradePathTest: test runner returned a non-zero error code (255).
- Found database prefix 'simpletest870634' for test ID 468.
[15-Aug-2012 17:42:17] PHP Fatal error:  Cannot use object of type stdClass as array in /var/lib/drupaltestbot/sites/default/files/checkout/core/includes/bootstrap.inc on line 2901

but that doesn't appear (from what I can figure out) to be anything that calls or is related to the drupal_get_filename function which is being modified.

Any suggestions welcome (not done much of this so still getting to grips with testbot)

tsphethean’s picture

Status:Needs work» Needs review
Issue tags:-Performance, -needs backport to D7, -Needs profiling

Status:Needs review» Needs work
Issue tags:+Performance, +needs backport to D7, +Needs profiling

The last submitted patch, drupal_get_filename_cache-1081266-69.patch, failed testing.

tsphethean’s picture

StatusFileSize
new7.09 KB
FAILED: [[SimpleTest]]: [MySQL] 40,038 pass(es), 97 fail(s), and 82 exception(s).
[ View ]

Ah - error in the variable name I was saving in the cache set following the file scan.

This now passes the failing test in my local environment now so resubmitting.

tsphethean’s picture

Status:Needs work» Needs review

Status:Needs review» Needs work
Issue tags:-Performance, -needs backport to D7, -Needs profiling

The last submitted patch, drupal_get_filename_cache-1081266-74.patch, failed testing.

tsphethean’s picture

Status:Needs work» Needs review

Status:Needs review» Needs work
Issue tags:+Performance, +needs backport to D7, +Needs profiling

The last submitted patch, drupal_get_filename_cache-1081266-74.patch, failed testing.

tsphethean’s picture

Definitely confused by these test failures. All upgrade path tests pass on my local site. Does anyone else get any failures from this patch?

tsphethean’s picture

Status:Needs work» Needs review
StatusFileSize
new7.24 KB
Test request sent.
Previous result: FAILED: [[SimpleTest]]: [MySQL] 40,161 pass(es), 97 fail(s), and 82 exception(s).
[ View ]

Updated patch - passes tests locally.

Status:Needs review» Needs work

The last submitted patch, drupal_get_filename_cache-1081266-80.patch, failed testing.

BrockBoland’s picture

Needs issue summary

disasm’s picture

corbacho’s picture

andypost’s picture

Spleshka’s picture

I think that every time when admin submits module list, Drupal should check all enabled modules and clean up orphaned file names from {system} table.

mikeytown2’s picture

Issue tags:-needs backport to D7

The patch for D7 works great, the D8 patch has issues. Thus I'm changing the tags to show this.

Spleshka’s picture

D7 patch looks good to me too.

mgifford’s picture

Status:Needs work» Needs review
mgifford’s picture

If you use http://drupal.org/project/clean_missing_modules then this shouldn't be a problem right?

The patch in #80 is for D7 or D8? Just the Version is for D8, but people are talking about applying this to D7.

@tsphethean any direction on where this should be applied? It can't be for both D7 & D8.

mikeytown2’s picture

#80 is for D8

tsphethean’s picture

Sorry, yes - #80 is a D8 patch but is pretty old so might need a re-roll.

tsphethean’s picture

StatusFileSize
new7.09 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch drupal_get_filename_cache-1081266-93.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]

Trying a re-roll against latest D8 build.

Status:Needs review» Needs work

The last submitted patch, drupal_get_filename_cache-1081266-93.patch, failed testing.

tsphethean’s picture

StatusFileSize
new7.09 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch drupal_get_filename_cache-1081266-95.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]

Fixing whitespace issue which prevented patch applying.

tsphethean’s picture

Status:Needs work» Needs review

Queue for testing

Status:Needs review» Needs work

The last submitted patch, drupal_get_filename_cache-1081266-95.patch, failed testing.

tsphethean’s picture

Ok think I've made a mess of my local site - rebuilding and will re-roll the patch by hand tomorrow.

tsphethean’s picture

Having a bit of a look at the revised drupal_get_filename in D8 I'm actually having a few second thoughts about my original approach. We're now doing:

$file_list = state()->get('system.' . $type . '.files');

To get a list of all the files in the system, and then building up the array. Not knowing too much about the new state system, is this going to be DB level state in the first instance, so would benefit from the eventual $files array being cached, or is state going to be cached anyway by the state interfaces?

Grateful for pointers... happy to proceed if it seems worthwhile. Still getting to grips with state, config and things :-)

beejeebus’s picture

StinkFoot’s picture

Output of dry-run 1081266-58-drupal_get_filename-D7.patch on Drupal 7.18

patch --dry-run < bootstrap.patch
patching file bootstrap.inc
Hunk #1 succeeded at 816 (offset -27 lines).
Hunk #2 succeeded at 867 (offset -27 lines).
patch unexpectedly ends in middle of line
Hunk #3 succeeded at 895 with fuzz 1 (offset -27 lines).

mikeytown2’s picture

StatusFileSize
new1.75 KB
PASSED: [[SimpleTest]]: [MySQL] 39,617 pass(es).
[ View ]

Re-roll of #58 against the latest D7 dev

mikeytown2’s picture

Version:8.x-dev» 7.x-dev
Status:Needs work» Needs review

Going to test #102 on D7 via testbot. Will move issue back to D8 once patch goes green.

mikeytown2’s picture

Version:7.x-dev» 8.x-dev
Status:Needs review» Needs work

#102 Passed all tests.
Moving back to 8.x and needs work.

StinkFoot’s picture

patch --dry-run < bootstrap.patch
patching file bootstrap.inc
Hunk #1 succeeded at 816 (offset 1 line).
Hunk #2 succeeded at 867 (offset 1 line).
patch unexpectedly ends in middle of line
Hunk #3 succeeded at 895 with fuzz 1 (offset 1 line).

After that, used TextWrangler to ´normalize´ line endings, same result.

mikeytown2’s picture

@StinkFoot
I think you need to use -p1 with your patch commands.

Dry run:

git apply --check -p1 drupal-1081266-102-drupal_get_filename-D7.patch
OR
patch --dry-run -p1 < drupal-1081266-102-drupal_get_filename-D7.patch

Apply:

git apply -v -p1 drupal-1081266-102-drupal_get_filename-D7.patch
OR
patch -p1 < drupal-1081266-102-drupal_get_filename-D7.patch
StinkFoot’s picture

@Mikeytown2

Thanks for your support!

After reading what the option does, I´ve looked inside the file and - please correct me if I´m getting this wrong - I see that patch will be looking at

a/includes/bootstrap.inc
b/includes/bootstrap.inc

Patch documentation reads:

For all pathnames in the patch file that indicate the names of files to be patched, delete num pathname components from the beginning of each pathname. If the pathname in the patch file is absolute, any leading slashes shall be considered the first component (that is, -p 1 shall remove the leading slashes). Specifying -p 0 shall cause the full pathname to be used. If -p is not specified, only the basename (the final pathname component) shall be used.

So, NUM would be 3.

Omitting -p should result in patch using the final component and since I run patch in the same directory, that should work.

I tried p0 up to p4 and get the same result every time, so... I am not to sure about your suggestion.

But, always eager to learn, so please enlighten me if I don´t know what I am doing:-)

Merry Xmas!

Update:

After reading my own comment, decided to test the procedure by creating the directories and try to apply the patch from their mutual parent.
Failed.

Lukas von Blarer’s picture

I am running the patch in #102 in production since today and I am experiencing an insane improvement. My page load times went from 2200ms down to 500ms! So far I am not facing any problems. Thank you!

PlayfulWolf’s picture

Is this patch already applied on last D7?

mikeytown2’s picture

@PlayfulWolf
Don't think so. https://api.drupal.org/api/drupal/includes!bootstrap.inc/function/drupal...

D7 patch #102 is RTBC, D8 is still needs work.

mikeytown2’s picture

Issue summary:View changes

Created an issue summary.

nbourdial’s picture

Hi,
any idea when the #102 patch will be commited and released to the next D7 release ?
For info, the patch saved 3.5sec for each page load (7sec -> 3.5sec), for a Drupal instance with about 250 modules enabled !

Thanks for the patch anyway !

oriol_e9g’s picture

Only for information, I'm using this code since D6 to remove all missing files from system table.

Why we can't add a similar cleanup process every time we launch update.php?

<?php
/**
 * Remove missing modules.
 */
function mymodule_update_6001() {
 
$result = db_query("SELECT * FROM {system}");

 
$items = array();
  while (
$record = db_fetch_object($result)) {
   
$record->info = unserialize($record->info);
   
$items[$record->name] = $record;
  }

  foreach (
$items as $item) {
    if (!
file_exists($item->filename)) {
     
$ret[] = update_sql("DELETE FROM {system} WHERE filename = '" . $item->filename . "'");
    }
  }

  return
$ret;
}
?>
nicholas.alipaz’s picture

Issue summary:View changes

I couldn't read through all of the over 100 posts here, but I thought that I would share how I was able to determin which missing modules were causing this issue on our server.

for i in $( drush sqlq "select filename from system where filename like 'sites/SITEDIRECTORY/%'" ); do if [ ! -f PLATFORMDIRECTORY/$i ]; then echo MISSING: $i;drush sqlq "select status from system where filename = '$i'"; fi; done;

Where PLATFORMDIRECTORY = '/var/www/drupal' and SITEDIRECTORY = 'example.com' or possibly 'all' depending on your setup.

Running that from cli will give you the name of any missing files and the status of the module that is missing. Example output:

MISSING: filename
MISSING: sites/www.example.com/modules/contrib/addressfield_phone/addressfield_phone.module
status
1
MISSING: sites/www.example.com/modules/contrib/taxonomy_menu_trails/taxonomy_menu_trails.module
status
0
MISSING: sites/www.example.com/modules/contrib/views_tree/views_tree.module
status
0

As you can see I found my module causing the issue.

mikeytown2’s picture

Adding tag to show that we have a RTBC 7.x patch in #102 but not a 8.x patch.

ChristophWeber’s picture

Applied #102 to 7.19 core, which has 148 enabled modules per drush pm-list, and runs on a well tuned cluster. We do not have any missing modules or files AFAIK.
Patch works well, no issues, but also no real speed improvement.

mikeytown2’s picture

@ChristophWeber
The speed improvement only happens if you have a missing module. Thanks for the info on the 7.x patch though.

marcelovani’s picture

I have a situation where an empty string is passed as parameter $name, which causes some extra loops for no reason.

This is also causing this error message:

The following module is missing from the file system: .

See a proposed fix here https://www.drupal.org/node/2383823#comment-9385897

I applied both patches (issue 9385897 and issue 9386005) and I can see they both work well together.

ps: I am using Drupal 7.34

jeroen.b’s picture

This issue is more relevant than ever, see the related issue.
I'll re-roll and test this patch soon.

mikeytown2’s picture

#102 still applies with an offset of 21 lines and is RTBC from my understanding. In order for this to get into D7 a patch for D8 needs to be created OR it needs to be proven that this is fixed or is no longer relevant in D8.

jeroen.b’s picture

StatusFileSize
new2.89 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 81,956 pass(es), 2 fail(s), and 1 exception(s).
[ View ]

Ah okay, thats good.
Checked in D8 beta 3, still seems relevant. Code got a rewrite but I think it still has the same issue.
New patch attached, created from D8 git head.

mikeytown2’s picture

Status:Needs work» Needs review

Status:Needs review» Needs work

The last submitted patch, 120: avoid_rescanning_drupal_get_filename-1081266-120.patch, failed testing.

jeroen.b’s picture

Hmm, guess watchdog isn't always available at that point. Any suggestions?

mikeytown2’s picture

Status:Needs work» Needs review
StatusFileSize
new4.12 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 81,957 pass(es), 1 fail(s), and 0 exception(s).
[ View ]

http://www.appneta.com/blog/drupal-8-watchdog/

Drupal::logger() is the way of the future; but your patch already uses that.

Drupal::logger() -> LoggerTrait::error() -> DbLog::log() which writes to the watchdog table. Having an error here seems like a separate issue.

The profile being missing has to do with the code in ExtensionInstallStorage::getAllFolders(); it calls drupal_get_profile() which returns NULL and then InstallStorage::getComponentNames
('profile', array(NULL))
is executed resulting in the error.

I've modified your patch in #120 so it won't call getComponentNames on a null array and I've also incorporated the fix for this from #2383823: drupal_get_filename() should check if $name is empty

Status:Needs review» Needs work

The last submitted patch, 124: drupal-1081266-124-avoid-rescanning-missing-module-D8.patch, failed testing.

mikeytown2’s picture

Line 28 is where it went fatal and it's the function definition.
https://api.drupal.org/api/drupal/core!modules!system!src!Tests!Bootstra...
Not sure where to go from here

EDIT:
Running the test locally I get
ResponseText:
( ! ) Fatal error: Call to a member function get() on a non-object in /core/lib/Drupal.php on line 262
Call Stack
#TimeMemoryFunctionLocation
10.0010150168{main}( )..\index.php:0
20.16301262768Drupal\Core\DrupalKernel->handle( )..\index.php:24
30.33404883904Stack\StackedHttpKernel->handle( )..\DrupalKernel.php:579
40.33404884008Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle( )..\StackedHttpKernel.php:23
50.33404884048Drupal\Core\StackMiddleware\PageCache->handle( )..\ReverseProxyMiddleware.php:58
60.37005466664Drupal\Core\StackMiddleware\KernelPreHandle->handle( )..\PageCache.php:52
70.42908183680Symfony\Component\HttpKernel\HttpKernel->handle( )..\KernelPreHandle.php:53
80.42908183928Symfony\Component\HttpKernel\HttpKernel->handleRaw( )..\HttpKernel.php:66
90.636011414640call_user_func_array
( )..\HttpKernel.php:145
100.636011414864Drupal\system\Controller\BatchController->batchPage( )..\HttpKernel.php:145
110.637011472440_batch_page( )..\BatchController.php:60
120.649012191896_batch_do( )..\batch.inc:83
130.649012192056_batch_process( )..\batch.inc:101
140.653012232128call_user_func_array
( )..\batch.inc:256
150.653012232264_simpletest_batch_operation( )..\batch.inc:256
161.880113557656Drupal\simpletest\TestBase->run( )..\simpletest.module:320
173.962217933560Drupal\system\Tests\Bootstrap\GetFilenameUnitTest->testDrupalGetFilename( )..\TestBase.php:869
183.972217980328drupal_get_filename( )..\GetFilenameUnitTest.php:39
193.972217980616Drupal::cache( )..\bootstrap.inc:270

Will work on this some more.

mikeytown2’s picture

StatusFileSize
new5.32 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 81,994 pass(es).
[ View ]

OK story is the testing framework sets https://api.drupal.org/api/drupal/core!lib!Drupal.php/function/Drupal%3A... to NULL. This causes all calls to the Drupal class to fail it seems; thus I feel like I'm missing something. I've edited the code to work around this so the tests pass.

https://api.drupal.org/api/drupal/core!tests!Drupal!Tests!UnitTestCase.p...

mikeytown2’s picture

Status:Needs work» Needs review
jeroen.b’s picture

Looks like a weird workaround. Are you sure it's the testing framework that sets it to NULL?
Maybe it's being called at a point where the Drupal class isn't initialized yet. I did not look that deep into D8 yet though so would have to do some more searching.

mikeytown2’s picture

Not 100% sure but according to the docs that is what it does

Sets a new global container.
Parameters

\Symfony\Component\DependencyInjection\ContainerInterface $container: A new container instance to replace the current. NULL may be passed by testing frameworks to ensure that the global state of a previous environment does not leak into a test.

mikeytown2’s picture

Brought this up in IRC and the workaround I created for this seems to be ok.

"The idea with that test is to ensure that drupal_get_filename() works in the bootstrap process in which the container is not there for a purpose." - dawehner

I'll document this so people know why we're checking types.

mikeytown2’s picture

StatusFileSize
new5.54 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 82,037 pass(es).
[ View ]

Added this comment to the code
In early stages of the bootstrap process the container may not be set inside of the Drupal class.

Status:Needs review» Needs work

The last submitted patch, 132: drupal-1081266-132-avoid-rescanning-missing-module-D8.patch, failed testing.

Status:Needs work» Needs review
beejeebus’s picture

passing NULL/FALSE/'' to method_exists is safe, so this:

<?php
+      if (!empty($cache_object) && is_object($cache_object) && method_exists($cache_object, 'get')) {
?>

can be shortened to:

<?php
+      if (method_exists($cache_object, 'get')) {
?>

this check:

<?php
+    if (empty($bad)) {
?>

will be true over and over again there's no data in $cache_object->get('drupal_get_filename:bad', TRUE);, which doesn't seem to fit the intention of the static. better to initialize the static as $bad as NULL, and check for is_null.

marcelovani’s picture

I can't see any problem in doing extra checks. Is that about having extra bytes in the code? making the execution slower?
We should seriously focus on getting this fix applied rather than debating what is better.
BTW, nothing can be worse than the current implementation.

jeroen.b’s picture

StatusFileSize
new5.39 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 82,039 pass(es).
[ View ]

I think @beejeebus is right though. Better fix it properly now.
You don't want to execute an SQL query (for a cache lookup) every time you hit that piece of code.

And extra checks can really make your code more unreadable, so why add extra checks when you don't need them?

jeroen.b’s picture

StatusFileSize
new1.8 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Unable to apply patch drupal-1081266-138-drupal_get_filename-D7.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]

And let's fix that mistake in the 7.x patch too while we're at it.

Status:Needs review» Needs work

The last submitted patch, 138: drupal-1081266-138-drupal_get_filename-D7.patch, failed testing.

jeroen.b’s picture

Version:8.0.x-dev» 7.x-dev

Status:Needs work» Needs review
jeroen.b’s picture

Version:7.x-dev» 8.0.x-dev

D7 patch passed, so back to D8

jeroen.b’s picture

Priority:Normal» Major

Changed to major as this issue keeps popping up for me, for example when you delete a module without uninstalling it (which could happen quite often when you use makefiles/profiles).

I also think more people are having this issue without them knowing it.

mikeytown2’s picture

Both patches (#137, #138) look good. +1 from me. Also agree that this is an under reported issue.

askibinski’s picture

Yes, this can really cripple your servers with high CPU loads.
Not only with deleted modules , but also if you have an unpatched version of imagecache_actions which contains a typo which triggers this bug.
#2166715: Typo causes extra query every page load

marcelovani’s picture

Status:Needs review» Reviewed & tested by the community

Lets get this committed, shall we?

Status:Reviewed & tested by the community» Needs work

The last submitted patch, 138: drupal-1081266-138-drupal_get_filename-D7.patch, failed testing.

jeroen.b’s picture

Hmm, how we get this working for D7 and D8 at the same time. Seems impossible...

marcelovani’s picture

Once they apply the patch on D8 they will change the issue to be backported to D7

marcelovani’s picture

Status:Needs work» Reviewed & tested by the community
StatusFileSize
new5.39 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 82,441 pass(es).
[ View ]

Re-submitting the patch

swentel’s picture

Status:Reviewed & tested by the community» Needs work
Issue tags:+Needs tests

Not a fan of the extra call of cache_get so early. The changes in Drupal.php to return NULL funky and shouldn't really happen there.

I'm also leaning more to the idea of cleaning up when installing/uninstalling modules, see comment #86.

Also, needs tests.

Berdir’s picture

What about adding a hook_requirements() check that looks for missing modules and gives you a link that you can click that will drop that module from the system?

That is also a good place to place a bold red warning that you should never ever just remove a module without uninstalling it first. We're putting a huge amount of efforts into D8 to make uninstallation save and not leaving behind configuration and data and not being able to uninstall when a module is still used, just removing a module breaks all that. What if that module for example provides a bundle or a field type that is still used?

oriol_e9g’s picture

+1000
See #112

I also think that it's better remove invalid entries than workaround.

joseph.olstad’s picture

jeroen.b's patch from comment # 137 and #138 makes sense to me

The following comments between #151, 152, 153 talk about Removing module schema information without having run a proper uninstall.

mikeytown2’s picture

Status:Needs work» Needs review
StatusFileSize
new3.75 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/includes/bootstrap.inc.
[ View ]

@swentel
I Didn't see Drupal::hasService(); will use that instead of the funky NULL as Drupal::hasService() is used elsewhere in drupal_get_filename(). Also moved the cache to right before we do a filesystem scan; prevents a cache get for the vast majority of calls. Thanks for the critique!

joseph.olstad is correct; removing module schema information without having run a proper uninstall is why this logs the missing module; so an admin can properly deal with it. Since the code is missing there is nothing drupal can should auto do.

Agree with Berdir; adding an additional check in hook_requirements for missing modules sounds like a good idea. I do think we need both solutions; hook_requirements & avoid re-scanning module directory. If we implement an additional check using hook_requirements, we could probably get rid of the logging inside of drupal_get_filename().

Status:Needs review» Needs work

The last submitted patch, 155: drupal-1081266-155-avoid-rescanning-missing-module-D8.patch, failed testing.

mikeytown2’s picture

Status:Needs work» Needs review
StatusFileSize
new3.76 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/includes/bootstrap.inc.
[ View ]

new patch with less php syntax errors™

Status:Needs review» Needs work

The last submitted patch, 157: drupal-1081266-157-avoid-rescanning-missing-module-D8.patch, failed testing.

mikeytown2’s picture

StatusFileSize
new3.76 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 82,539 pass(es).
[ View ]

Thinking I'll have to install D8 if this fails again...

mikeytown2’s picture

Title:Avoid re-scanning module directory when multiple modules are missing» Avoid re-scanning module directory when a module is missing
Status:Needs work» Needs review
jeroen.b’s picture

I just tested this against HEAD, \Drupal::hasService('cache') and \Drupal::hasService('logger') don't return TRUE, so the cache never gets created.

How would we create tests for this?
AFAIK \Drupal::hasService('cache') returns FALSE in the testsuite so we have to find some other way to test this.

Regarding #152, I think we should do that in a separate issue.

jeroen.b’s picture

StatusFileSize
new3.78 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 84,136 pass(es).
[ View ]

Ah, it had to be \Drupal::hasService('cache.bootstrap') and \Drupal::hasService('logger.factory')

New patch attached which fixes that. Just tested locally and now I get cache and a watchdog message.

joelpittet’s picture

Regarding #137 D7 version @jeroen.b

After applying that patch I got this error:

Exception: theme() may not be called until all modules are loaded. in theme() (line 1017 of /Users/joel/Sites/mysite/html/includes/theme.inc).

And on drush rr following that message:

WD system: The following module is missing from the file system: .

Second drush rr went through ok, but didn't resolve the first on page exception.

Omega 4 is the theme being used.

jeroen.b’s picture

@joelpittet
And you are sure those messages are related to this patch?

das-peter’s picture

@joelpittet Any chance you updated rules recently? Because: #2324587: Rules might be triggered too early in the bootstrap This can trigger the theme() exception as far as I remember.

joelpittet’s picture

Yes it was related to this patch it was the only one applied at the time, accept it was d7 patch in #138

@das-peter I just woke up but totally, I do plan on applying that when I get in. Thanks:)

joelpittet’s picture

Didn't have my coffee, re-read #165, I'll try them together and report back:)

joelpittet’s picture

@das-peter That rules patch in #165 didn't resolve the issues mentioned in #163 but that rules patch didn't cause any new problems, so far.

@jeroen.b #138 issues I mentioned in #163 are quite repeatable.

Directly after applying the patch, run registry rebuild.

The registry has been rebuilt via registry_rebuild (A).   [success]
http://site.dev|severity=alert|type=system|ip=127.0.0.1|uri=http://site.dev/|referer=|uid=0|link=|message=The following module is missing from the file system: .
WD system: The following module is missing from the file system: .   [error]
All caches have been cleared with drush_registry_rebuild_cc_all.    [success]
jeroen.b’s picture

@joelpittet
Can you pastebin the output of drush pm-list?
I can't reproduce, even when I use Omega.

I do think I have seen this behaviour before. I think it was when I did a drupal_get_path on a module that wasn't enabled/installed and also wasn't found on the filesystem. Nervermind that, that makes no sense.

joelpittet’s picture

Totally here, sorry it's long: https://gist.github.com/d7e1da8b7113e0f313cb

jeroen.b’s picture

StatusFileSize
new1.87 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Unable to apply patch drupal-1081266-171-drupal_get_filename-extra-debug-do-not-test-D7.patch. Unable to apply patch. See the log in the details link for more information.
[ View ]

Woah, that's too much to debug for me. Can you try the attached patch?
It adds an backtrace to the watchdog message because I think this is in some contrib module.

Status:Needs review» Needs work
joelpittet’s picture

Issue summary:View changes
StatusFileSize
new198.21 KB

@jeroen.b thanks for that it gave me an idea. The backtrace is super huge too, so weeding through that wouldn't be fun, I can still post it if you prefer, but I put a breakpoint there to see the context.

The $name is empty, but the $matched_name was addressfield.

Would that have an effect on this patch?

joelpittet’s picture

Digging through the callstack and two other modules were mentioned workbench_moderation and linked_field, though I have my money on workbench_moderation being the trouble maker... it's an invaluable module but has to fight harder than most to do what it does.

jeroen.b’s picture

Nah, addressfield just was the last value in the array $matches, so the last module it was able to find.

And seeing the menu_rebuild, now I remember where I have seen it before.
It's when you have a menu_item with a wrong "file path" value. Can you gist the backtrace?

joelpittet’s picture

Here's the backtrace: (formatted with pre in the patch)
https://gist.github.com/bf0ee1fe8feb398647ad

joelpittet’s picture

Oh elysia cron comes into the call stack too as the $parent in _menu_router_build()

$item['file path'] = drupal_get_path('module', $parent['module']);'

admin/config/system/cron

joelpittet’s picture

joelpittet’s picture

The module name is sometimes empty, I patched the elysia_cron one but the next one is with commerce commerce_tax_ui_tax_rate_title.

I'm trying to decide if this is something we can/should fix in this patch, or should I just use this and file patches on all those modules (daunting argh)

mikeytown2’s picture

Just a heads up #1158322-199: Add backtrace to all errors is handy for error backtracing. In this case, the linked issue wouldn't have helped; but I do find the linked issue to be super helpful.

joelpittet’s picture

StatusFileSize
new225.58 KB

The tax one doesn't have an issue opened up for it and it's a bit different but very similar.

The 'commerce_tax_ui' builds the hook_menu with
'file' => 'includes/commerce_tax_ui.admin.inc', but without a module key again. But in the screenshot the path has already been filled out... :S

jeroen.b’s picture

I can't reproduce that with the commerce_tax_ui.
Maybe there is some weird hook_menu_alter somewhere?

Anyway, I don't think we should fix these things in the patch. The stuff we find with this patch is already broken, only difference is that we can see what's broken now.
It's up to the maintainers now to fix their modules.

joelpittet’s picture

@jeroen.b very well could be, I'm a bit worried about the error produced in #137. Though I can't figure out why this patch would cause that at all... sorry for holding this up.

Grateful though that this indirectly solved elysia_cron issue.

jeroen.b’s picture

@joelpittet
Don't worry about holding this up, this issue has been here for a few years ;)
About the error in #137. Are you talking about the error you reported in #163?

Exception: theme() may not be called until all modules are loaded. in theme() (line 1017 of /Users/joel/Sites/mysite/html/includes/theme.inc).

This one?

I could not reproduce this. Not with a clean Drupal 7 HEAD, Drupal 7.34, Drupal 7.34 with Omega and Commerce.
Can you figure out what module (indirectly) calls theme()?

joelpittet’s picture

After repairing elysia cron I've not seen this error since but I'm keeping my eye on it, the patch is on my staging environment till I deploy the next round of changes.

jeroen.b’s picture

StatusFileSize
new5.44 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 87,309 pass(es).
[ View ]

I heard you guys want tests.
Here's a D8 patch with a testDrupalGetFilename() assert. I had to change the $bad records to a drupal_static to reach it from the test.
We can't use the bootstrap drupal_get_filename:bad cache for tests as the cache isn't available in the tests.

I'll look at tests for the D7 version later.

jeroen.b’s picture

Status:Needs work» Needs review
jeroen.b’s picture

I think these tags aren't relevant anymore

jeroen.b’s picture

StatusFileSize
new3.31 KB
PASSED: [[SimpleTest]]: [MySQL] 41,135 pass(es).
[ View ]

Here is a D7 patch with tests.

Status:Needs review» Needs work

The last submitted patch, 189: drupal-1081266-189-avoid-rescanning-missing-module-D7.patch, failed testing.

mikeytown2’s picture

Version:8.0.x-dev» 7.x-dev

changing to 7.x for testing

Status:Needs work» Needs review
jeroen.b’s picture

Issue tags:-Needs tests

All green. Let's get this committed?

swentel’s picture

Version:7.x-dev» 8.0.x-dev
Assigned:Unassigned» swentel
Status:Needs review» Needs work

Well, first of all, this should go in D8 first. Secondly, see comment #150 and #151. Doing this kind of optimization at run-time really isn't the proper way to fix this bug. To be clear: it is a bug (sometimes extremely annoying), I've actually hit it a couple of times as well, but I disagree that we should fix this at run time. There are better, cleaner ways (order is my preference)

  1. hook_requirements() with a link to clean up
  2. running update.php
  3. when submitting the modules page
  4. maybe, maybe, maybe when clearing full caches, although that's maybe over the top

I'm in favor of number 1 because we then also have a UI that informs the user which module(s) are actually missing. All the other variants, which may trigger watchog, are less obvious and are easily missed.

I'm in London next week for drupalcamp london, I'll try to write up a patch during those days.

jeroen.b’s picture

I'm all for really fixing this, but sometimes that just not possible by just cleaning the registry.
Sometimes other modules call drupal_get_path manually with wrong arguments, or with disabled modules, I have seen a couple of cases.

Sometimes you can't properly uninstall a module, we deploy all sites with drush make, if we remove the module from the makefile, the record is still in the registry.

My plan was to get this patch committed and then create a new issue where we add the hook_requirements functionality. If you want to include that in this patch that's fine with me, but please also use the existing patches.
Currently if something goes wrong in drupal_get_filename, you have absolutely no idea.