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

We cache any missing files in a static variable as well as in cache_bootstrap (for about 24 hours, or until we visit the themes/modules overview page). We also do a trigger_error() as soon as we find a missing module.

In a followup issue we can check for this in hook_requirements() as well.

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.

This information will be cached in 'drupal_get_filename:missing' in cache_bootstrap as well. Invalidation of this cache happens upon running cron, and upon visiting the themes/modules overview pages.

Beta phase evaluation

Reference: https://www.drupal.org/core/beta-changes
Issue category Bug because significant performance slowdown
Issue priority Major because significant performance slowdown.
Prioritized changes The main goal of this issue is performance
Disruption N/A
Files: 
CommentFileSizeAuthor
#289 1081266-289.patch15.11 KBstefan.r
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,788 pass(es).
[ View ]
#289 interdiff-266-289.txt4.06 KBstefan.r
#287 1081266-287.patch15.23 KBstefan.r
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,759 pass(es), 0 fail(s), and 4 exception(s).
[ View ]
#287 interdiff-283-287.txt1.24 KBstefan.r
#284 1081266-283.patch13.77 KBstefan.r
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,767 pass(es), 0 fail(s), and 11 exception(s).
[ View ]
#284 interdiff-266-283.txt2.91 KBstefan.r
#282 1081266-282.patch13.77 KBstefan.r
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/lib/Drupal/Core/Config/ConfigInstaller.php.
[ View ]
#282 interdiff-281-282.txt1.48 KBstefan.r
#281 1081266-281.patch13.47 KBstefan.r
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,705 pass(es), 0 fail(s), and 719 exception(s).
[ View ]
#281 interdiff-278-281.txt1.23 KBstefan.r
#279 1081266-278.patch12.13 KBstefan.r
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,726 pass(es), 0 fail(s), and 730 exception(s).
[ View ]
#279 interdiff-277-278.txt363 bytesstefan.r
#277 interdiff-274-277.txt907 bytesstefan.r
#277 1081266-277.patch12.17 KBstefan.r
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/lib/Drupal/Core/Config/ExtensionInstallStorage.php.
[ View ]
#274 1081266-274.patch11.16 KBstefan.r
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,714 pass(es), 0 fail(s), and 799 exception(s).
[ View ]
#274 interdiff-266-274.txt551 bytesstefan.r
#266 1081266-266.patch11.5 KBstefan.r
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,695 pass(es).
[ View ]
#266 interdiff-260-266.txt1.16 KBstefan.r
#261 1081266-260.patch11.95 KBstefan.r
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,428 pass(es).
[ View ]
#261 interdiff-254-260.txt1.51 KBstefan.r
#258 interdiff-223-254.txt9.3 KBstefan.r
#254 1081266-254.patch11.94 KBstefan.r
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,982 pass(es).
[ View ]
#252 interdiff-233-248.txt9.05 KBstefan.r
#248 1081266-248.patch11.91 KBstefan.r
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,981 pass(es).
[ View ]
#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 ]

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.

mikeytown2’s picture

Assigned:swentel» Unassigned
joseph.olstad’s picture

I agree with jeroen.b , there's going to be situations where admins of large scale sites managed by committee that can't just decide by themselves if or when to cleanup something and determine if it was something left by a drush make or if it was a module that was removed from the filesystem by mistake. The best approach is his solution because it fixes the performance problem and also is noisy enough so that admins will be able to see what is going on and let them take a reasonable course of action without a huge performance penalty.

Prior to this patch not only are admins left in the dark but there's also a huge performance penalty. Lets get this committed. We've been running patch #102 in production for a while and I just reviewed patch 189 and it looks good. So for those working on D8, please follow the advice of jeroen.b because not only do we want to see D8 improve but we also are running production D7 sites that pay for our work on D8.

heyyo’s picture

I'm using the patch from #189, I'm not sure what's wrong but it reports me this error:
"The following module is missing from the file system: mothership"
Mothership is not a module, but a theme, and this theme is present in sites/all/themes.
Mothership is not enabled(but was enabled before), I had the version 2.x before, but now I'm using 3.x.
Not sure how to fix that ?

SocialNicheGuru’s picture

@heyyo, do a "grep -in mothership" in your module and themes directory.
There is probably a call to a file in that module somewhere or a misspelling.

an issue where something like this occurred to me:
https://www.drupal.org/node/2428105

here is another:
https://www.drupal.org/node/2375741

heyyo’s picture

Thanks a lot @SocialNicheGuru it was indeed the problem with this file mothership/mothership/panelsstyles/motherstyle/motherstyle.inc
Including 3 times :

<?php
'path'    => drupal_get_path('module', 'mothership') .'/panelsstyles/motherstyle'
?>
joseph.olstad’s picture

StatusFileSize
new4.42 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,705 pass(es).
[ View ]

The nice patch from by jeroen.b from comment #186 needed to be refactored after D8 core commit #40cc6312 for issue #2090115 by alexpott, xjm: Don't install a module when its default configuration has unmet dependencies.

Attached is a refactored patch for D8 accordingly.

joseph.olstad’s picture

Status:Needs work» Needs review

D8 patch #202 passed all tests march 26, 2015 22:00 0400+gmt
D7 patch #189 passed all tests in February 2015
D6 not yet backported, lets commit the D8 and D7 patch first.

David_Rothstein’s picture

Adding a cache to this kind of low-level function looks odd to me (others above have said the same thing)... Also there is no code that ever clears the cache (except on a sitewide cache clear)? Can't it get stale?

+    if (\Drupal::hasService('logger.factory')) {
+      \Drupal::logger('system')->error('The following @type is missing from the file system: @name', array('@type' => $type, '@name' => $name));
+    }

Maybe a simple trigger_error() is better here? That should get it into the logs anyway, plus onto the screen on dev sites (a key part of this, so developers can find mistakes in their code that lead to this). This is sort of getting into the territory of #2380361: Latest tweaks to bootstrap.inc can make Drupal sluggish when there is code that tries to load a file that doesn't exist but the two issues are closely related. I tend to think warning about this problem is realtime is better than trying to fix it with a cache in realtime.

joseph.olstad’s picture

When developers are removing things from the filesystem they're usually:
A) running a drush make script
B) performing filesystem operations perhaps from a script
C) changing in or out modules, in which case a full cache clear is run.
D) upgrading a Drupal site from one distribution to another
E) upgrading a Drupal distribution from one version to another (that may be missing files seen in previous versions and lacks appropriate hook_updates)
F) upgrading Drupal core and forgot to restore a folder such as sites/all/modules/contrib
G) any combination of the above combined with updatedb

Also there is no code that ever clears the cache

operations C, D, E, F, G will trigger a site-wide cache clear, so the cache is not stale.

Adding a cache to this kind of low-level function looks odd to me

and so does re-scanning module directory when a module is missing

Maybe a simple trigger_error() is better here

sure it would be nice what about the performance issue? Example: webform_conditionals from webforms 3.x was swallowed up by webforms 4.x , but if you run a pm_uninstall on webform_conditionals 3.x are you sure that you're not going to remove tables that are now used by webforms 4.x? So now you have a performance issue while your production site which needs the new features from this new module that swallowed up another module but the schema table says it's still installed but you've removed it from the filesystem because the webforms readme.txt told you to do so. No one paid attention to this before until they realised their site was slower than it used to be so they went on to find some performance fixes and applied this patch. Now they're aware of multiple other problems that they were not aware of, but no problem, this patch fixes the performance issue without having to immediately deal with the mess undernieth that you will need a committee to sit together and point the finger and look at test results and build behat tests for and wait for approval to make the necessary changes, meanwhile the clients are frustrated that your site is slow except with this patch thankfully we get both INFORMED and RESTORED PERFORMANCE.

Meanwhile, much of the drupal community sits in ignorance wondering how entropy is creeping in and slowing down their sites, not knowing how to resolve it, they start thinking that the best solution is to re-install and start from scratch and hope that the performance problem doesn't come back. Or worse yet, they say, hey, lets install Joomla instead.

Why don't we just commit the patches, illuminate the drupal community and put the smiles back on the developers faces and the confidence back in their ability to administer sites, we get performance back and we also get informed of what is going on! Otherwise we're completely oblivious as to what is happening and why our sites become so damn slow over time. Finding this patch was a stroke of good luck. Thanks to all those that created it and pushed it forward.

RTBC + please

mikeytown2’s picture

100% agree with joseph.olstad #205.

Will also say caching a bad list makes sense due to typo's when calling drupal_get_path(), see #199. Also see this issue where the bad module name was ''. Having your site be slow while you have no idea where to look sucks #2407129: Missing module<empty> on menu rebuild because of bad admin/config/system/cron override. These 2 issues point out that with the mothership theme or the Elysia Cron module installed and this patch not enabled results in a much slower Drupal install for those using the code; which is around 20k sites (counting the d7 installs).

I agree that in an ideal world we wouldn't need a cache here; but we're on the web where bad things happen all the time (typos) and bureaucracy can tie your hands.

joseph.olstad’s picture

A while ago I created a drush tool for detection and auto cleanup of phantom modules based on comment #112 however even with that, my tool only cleans out phantom modules and does not yet clean out phantom themes. With that said, I have run it on one production site but not on another. The patch that everyone here has worked hard on over the past 4 years correctly informs us and gives us the luxury of delaying such a cleanup without a performance penalty. There may be some scenarios where a cleanup has to be delayed for long periods of time. I think we've already outlined the importance of this but just to show you how much this issue is important it's why I am sharing this.

joseph.olstad’s picture

A small drip for Dries and D8, a nice warm douche for all of Drupal kind!

David_Rothstein’s picture

When developers are removing things from the filesystem they're usually ... trigger[ing] a site-wide cache clear, so the cache is not stale.

True, I guess the cache only goes stale if a missing module in the filesystem is added back, and most people probably do expect to have to clear the site's caches when doing something as big as adding a new module (although it's not always technically required now).

Keep in mind that for the trigger_error() solution, it would not just be that - the idea would be to combine it with something like #195 to fix the cases that actually can be fixed. (I'd add "run it on cron" as a possible option to the list of places in that comment where the fix could be done, by the way.)

jeroen.b’s picture

Replacing the watchdog with trigger_error() is fine with me. I'll see if I can update the patch soon.

I also agree with joseph.olstad here. Why don't we RTBC this and figure out #195 in another issue?
As in my opinion idea 1 (which I think is the way to go) from #195 requires a new discussion and it only addresses a small part (dirty system table) of what this patch addresses.

Fabianx’s picture

Status:Needs review» Reviewed & tested by the community

I am moving this back to RTBC, I think the cache is okay, because it can only get stale if you add a new module or move a module and then the module_implements cache is as much a problem as this cache.

stefan.r’s picture

Is the D7 patch in #189 in sync with the D8 patch, and equally RTBC, so both can be committed at the same time? Or does the D7 patch need work still?

jeroen.b’s picture

D7 and D8 patches are in sync, they contain the same fixes and tests.

Fabianx’s picture

#212 However 8.0.x needs to be committed first and then the D7 patch is discussed.

alexpott’s picture

Status:Reviewed & tested by the community» Needs work
+++ b/core/includes/bootstrap.inc
@@ -208,10 +208,23 @@ function config_get_config_directory($type = CONFIG_ACTIVE_DIRECTORY) {
+  // We use drupal static for the bad records so we can test it.
...
+    $drupal_static_fast['bad'] = &drupal_static(__FUNCTION__ . ':bad');

bad is a really odd name. How about missing or something more descriptive.

Also the issue summary needs a update since it says that we're only going to statically cache this but no we're putting it in cache_bootstrap too. Which like others before me I'm incredibly dubious of. If you move a module by mistake and break your site, it ends up in the cache, you quickly fix your mistake and then it is still not fixed until you obliterate all the caches. I'd prefer to be more conservative here and just implement the static cache.

jeroen.b’s picture

Yes, in that one example, the cache might be a bit of a struggle. However, in most other examples the cache will come in very handy as this function might be very heavy on every page load.

When I would do something like moving a module by mistake and then place it back, my first idea would be to drush rr and drush cc all...

joseph.olstad’s picture

Jeroen.b makes another valid point in #216 that re-iterates what I already described in #205. We have a high performance solution here that is very practical in realworld use, many have been using it in production (at least the D7 version) and is urgently needed for those that are unaware that they need it (because everyone running Drupal should have this fix). I'm not sure why we keep going back to needs work. 4 years of work, it's more than enough time. IMHO, there aren't enough valid reasons to redesign at this point something that is practical in the realworld as this is and guarantees that performance will not be affected by bone-head operations. Meanwhile admins will be aware of what is going on. All of this has been stated many times.

*everybody* using Drupal needed this 4 years ago when this issue was openned (or even 8 years ago when people didn't know the problem existed but they should have had this fix) and people still need this today and they'll need it tomorrow, those that don't have it should have it.

alexpott’s picture

Caching a cache miss - which is what we are doing is generally a really bad idea. That said perhaps it is an acceptable trade-off if we ignore or clear this cache when we list modules or themes. Or rebuild it on cron as suggested by @David_Rothstein in #209

And bad is still a bad name :)

Fabianx’s picture

At least in Drupal 7 we can use CACHE_TEMPORARY for clearing on cron and a low ttl (24 hours?) for Drupal 8 instead of CACHE_PERMANENT.

In addition to that clearing this when visiting the admin/modules page sounds good to me.

We used to rebuild block caches since ages when visiting the blocks page, so that makes sense.

#218

Caching cache-misses is strange, right, but not caching cache misses is kind of an anti pattern too.

Usually:

<?php
$cached
= cache_get('key');

if (
$cached) {
  return
$cached->data;
}

// rebuild $data
$data = complex_operation();

cache_set('key', $data);

return
$data;
?>

So every cache_get() should usually be followed by a cache_set, which includes setting empty values or FALSE.

That said, we can't store the information that the module is not there in the original modules files cache?

#217: Keep pushing with good focus (and address feedback) and it will get in - one day :). Most issues that have someone dedicated to them found their way into core eventually.

Issues like this stall only for years, because they are sitting waiting for review or feedback or ... And usually that is lack of "resources" rather than lack of interest.

joseph.olstad’s picture

Alexpott, you proposed two options: "ignore or clear this cache when we list modules or themes"
this seems like a reasonable option (to ignore the cache for that case, clearing it is really not necessary as Jereon.b and I have previously explained)

However : "Or rebuild it on cron as suggested by @David_Rothstein in #209"
I am less favourable of this option because cron is already very resource intensive and doesn't need more load.

with that said, I like even better the "acceptable tradeoff" as you stated that the current patch gives. Slam dunk this.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new5.64 KB
new6.83 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,917 pass(es).
[ View ]

I concur with joseph.olstad about the importance of fixing this ASAP, and while I agree this is not an ideal implementation I quite like both suggestions in #219 as acceptable workarounds.

This path renames bad to missing and invalidates the missing file cache on cron runs as well as when visiting module/theme list pages.

stefan.r’s picture

Actually this patch doesn't clear the static cache so whoever visits the site right after a cron run may still be hit with a slowdown, correct?

I assume that if we have missing files, clearing up the static cache as well as the Drupal cache in the middle of a cron run will mean that we rebuild it further down that same cron run as there's likely new calls to drupal_get_filename()? Or should we clear the caches of the module/theme lists for that as well?).

I realize that load going up during cron runs is a concern, but that's what we can do a hook_requirements() thing for in a follow-up issue, and besides, I think it still beats giving significant load slowdowns to unlucky users visiting right after a cache clear :)

stefan.r’s picture

StatusFileSize
new7.01 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,919 pass(es).
[ View ]
new1.58 KB
stefan.r’s picture

Issue summary:View changes

Updated issue summary.

stefan.r’s picture

So I assume this patch would also fix this performance regression listed in the 7.33 release notes?

There is a performance regression after updating to Drupal 7.33 on sites that have code which tries to load a file that doesn't exist - this can cause a file system scan every time the code is called. Finding and fixing the offending code is the best solution. See #2380361: Latest tweaks to bootstrap.inc can make Drupal sluggish when there is code that tries to load a file that doesn't exist for further details.

stefan.r’s picture

Created followup issue over at #2464601: Check for missing modules in hook_requirements so we can do both the caching fix as well as a hook_requirements fix as suggested by many in this issue.

Just wondering if checking the system table in D7 and checking system.module.files / system.theme.data in D8 is enough, or if these missing files can come from elsewhere as well? (in which case we may want to get a list of these files by checking the missing files cache)

joseph.olstad’s picture

ok, so Stefan.r played it safe and went with both recommendations by Alexpott. Good job.

Alexpott, please review this and commit it to D8 so we can agree on a backport to D7 and commit that too!

stefan.r’s picture

@joseph.olstad I had missed your comment over in #220.

I am fine with updating the patch so it merely ignores the cache on admin theme/module pages instead of invalidating it, if we can get a committer to sign off on that :)

Fabianx’s picture

Status:Needs review» Reviewed & tested by the community

As {system} is more a registry than a cache I am okay with the patch to catch misses, lets see what Alex says.

Invalidation is better than ignoring, else you wonder why the module page is correct, but your system still does not see the new module, which is worse DX. Invalidation on cron is also not costly.

#227: Please do not tell core committers what to do or not do. There is a lot of voluntary work in there as well and it borderline almost violates our code-of-conduct (not really, but please treat core committers as other fellow co-workers).

I know that the core process can be slow at times, but all recommendations by core committers are done for the whole good of the whole Drupal ecosystem!

I have seen both in Drupal as well as in client work, lines of code that have been 'very simple change', it is so obvious, etc.

And some of them have made quite big problems later. Trust me in the end following the process and getting through good peer review will make Drupal for all of us better in the end.

joseph.olstad’s picture

@Fabianx , invalidation has a performance cost, so it's not necessarily better than ignoring. Stefan.r sees the point in #227. See reasons outlined by Jereon.b in #216 and myself in #205.

I'm fine either way, prefer ignoring the cache to invalidation as I stated previously (because invalidation defeats the purpose of a cache and again for the same reasons already explained). But close enough.

jeroen.b’s picture

#225, yes, I think it's the same issue, maybe it should be marked as duplicate?
Also, what about the trigger_error() idea from #204? trigger_error() will make the error be catched by Drupal's error handler which is more advanced than just a watchdog call.

Rest of the patch in #223 looks fine to me.

stefan.r’s picture

Status:Reviewed & tested by the community» Needs work

Yes @David_Rothstein's suggestion makes sense, let me do a patch.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new684 bytes
new6.96 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,964 pass(es), 0 fail(s), and 6 exception(s).
[ View ]

This adds the trigger_error().

Status:Needs review» Needs work

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

stefan.r’s picture

OK so this test fails because we do things like this in the tests:

GetFilenameUnitTest.php:

<?php
   
// Searching for an item that does not exist returns NULL.
   
$this->assertNull(drupal_get_filename('module', uniqid("", TRUE)), 'Searching for an item that does not exist returns NULL.');
?>

AttachedAssetsTest.php

<?php
  $build
['#attached']['library'][] = 'unknown/unknown';
   
$assets = AttachedAssets::createFromRenderArray($build);

   
$this->assertIdentical([], $this->assetResolver->getJsAssets($assets, FALSE)[0], 'Unknown library was not added to the page.');
?>
Fabianx’s picture

  1. +++ b/core/includes/bootstrap.inc
    @@ -251,13 +264,24 @@ function drupal_get_filename($type, $name, $filename = NULL) {
    +      if (is_null($missing)) {

    We use !isset() instead of is_null() in core.

    See http://3v4l.org/11S72 - it works.

  2. +++ b/core/includes/bootstrap.inc
    @@ -251,13 +264,24 @@ function drupal_get_filename($type, $name, $filename = NULL) {
    +        if (\Drupal::hasService('cache.bootstrap')) {
    +          $cache = \Drupal::cache('bootstrap')->get('drupal_get_filename:missing', TRUE);
    +          if ($cache && $cache->data) {

    We don't want to use , TRUE here as we don't deal with invalid data.

  3. +++ b/core/includes/bootstrap.inc
    @@ -265,6 +289,16 @@ function drupal_get_filename($type, $name, $filename = NULL) {
    +      \Drupal::cache('bootstrap')->set('drupal_get_filename:missing', $missing, REQUEST_TIME);

    Third parameter should be omitted.

    Currently we cache this for < 1s, hence the need to use TRUE above ...

    Edit:

    Use REQUEST_TIME + 24 * 60 * 60

    to store this for 24 hours.

    It will then automatically be cleaned up by the next cron run.

  4. +++ b/core/modules/system/src/Controller/SystemController.php
    @@ -186,6 +186,12 @@ public function systemAdminMenuBlockPage() {
    +    //  Clean up the bootstrap "missing files" cache when listing themes.
    +    if (\Drupal::hasService('cache.bootstrap')) {
    +      \Drupal::cache('bootstrap')->invalidate('drupal_get_filename:missing');
    +      drupal_static_reset('drupal_get_filename:missing');
    +    }

    Should use ->delete() and no need to check for the service.

    I think we want to inject the cache.bootstrap service instead here, but that we can do once the rest of the patch is sound.

  5. +++ b/core/modules/system/src/Form/ModulesListForm.php
    @@ -174,6 +174,12 @@ public function buildForm(array $form, FormStateInterface $form_state) {
    +    //  Clean up the "missing files" cache when listing modules.
    +    if (\Drupal::hasService('cache.bootstrap')) {
    +      \Drupal::cache('bootstrap')->invalidate('drupal_get_filename:missing');
    +      drupal_static_reset('drupal_get_filename:missing');
    +    }

    Should use ->delete(), and this can rely on the cache.bootstrap being available already.

  6. +++ b/core/modules/system/system.module
    @@ -1201,6 +1201,12 @@ function system_cron() {
    +  if (\Drupal::hasService('cache.bootstrap')) {
    +    \Drupal::cache('bootstrap')->invalidate('drupal_get_filename:missing');
    +    drupal_static_reset('drupal_get_filename:missing');

    Should use ->delete() instead of ->invalidate().

    And yes, re-calculating system files once after each cron run is acceptable.

    That said I think we should let garbage collection do the job for us.

Here is a more extensive review.

Fabianx’s picture

#235: That is a unit test, which should probably be moved to its own method with @expectedException annotation present:

https://phpunit.de/manual/current/en/writing-tests-for-phpunit.html#writ...

stefan.r’s picture

Probably expectedExceptionMessage would be better as if I give the exception type to expectedException it will work like the "@" operator and hide all errors which would hurt the test. There's also 6 test fails and not all of those are PHPUnit tests...

For the other ones maybe we could temporarily set a different error handler which ignores "file not found" warnings?

E_USER_NOTICE still triggers exceptions on the testbot right?

Berdir’s picture

Those are kernel tests. phpunit tests could not be calling functions.

stefan.r’s picture

So currently I'm leaning toward setting set_error_handler() / restore_error_handler() before and after the problematic statements and filtering out file not found warnings...

<?php
 set_error_handler
(function($severity, $message, $file, $line) {
     
// Skip error handling if this is a "file not found" error.
     
if (!(error_reporting() & $severity) || strstr($message, 'is missing from the file system:')) {
        return;
      }
      throw new
ErrorException($message, 0, $severity, $file, $line);
    }


   
// Look for missing file

   
restore_error_handler();
?>
stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new9.84 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/modules/system/src/Tests/Bootstrap/GetFilenameUnitTest.php.
[ View ]
new7.14 KB

Status:Needs review» Needs work

The last submitted patch, 241: 1081266-241.patch, failed testing.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new11.8 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/modules/system/src/Controller/SystemController.php.
[ View ]
new3.56 KB

Status:Needs review» Needs work

The last submitted patch, 243: 1081266-243.patch, failed testing.

stefan.r’s picture

StatusFileSize
new11.88 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,717 pass(es), 201 fail(s), and 81 exception(s).
[ View ]

Missed a comma.

stefan.r’s picture

Status:Needs work» Needs review

Status:Needs review» Needs work

The last submitted patch, 245: 1081266-244.patch, failed testing.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new11.91 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,981 pass(es).
[ View ]
new3.56 KB

Status:Needs review» Needs work

The last submitted patch, 248: 1081266-248.patch, failed testing.

stefan.r’s picture

Status:Needs work» Needs review

Queueing this for re-testing this to make sure this wasn't a fluke as I haven't seen the current test fail in MigrateFileTest with this patch before.

Also just to summarize for reviewers, in terms of changes to the last reviewed patch, this patch:

  • Fixes failing tests, where we remove nonexistent modules or set a custom error handler.
  • Cleans up code as per @Fabianx suggestions.
  • Sets an expiration of 24 hours on the "missing files" cache as suggested by @Fabianx. This means the cache ceases to explicitly clear during every cron run. Instead, it relies on garbage collection, as the cache will be invalidated once it's expired.

@Fabianx just to double check that this invalidation won't break anything, why did you ask to delete instead of invalidate the cache on the admin/theme pages? Won't an invalid cache mean just that when we try to do a get() the cache won't return anything (as $allow_invalid is now set to FALSE), and the cache will just be reset next time we try to do a cache_set(), or during garbage collection in cron?

Lastly, I may be wrong but I think ceasing to explicitly clean up the cache on every cron run also means that the cache will only be cleared once it's been fully built and all missing files have been found. This as any time a new missing file is found the expiration date is set further into the future. In the edge case of any code referring to a nonexisting file with a random file name, that could mean the cache never gets cleaned up. Is that something we can live with? If not, maybe we could set a fixed expiration date of 24 hours that doesn't get bumped further into the future every time the cache is updated?

stefan.r queued 248: 1081266-248.patch for re-testing.

stefan.r’s picture

StatusFileSize
new9.05 KB

OK this is green again.

joseph.olstad’s picture

Here's my test plan for D8:

1) install fresh with the patch
2) create a dummy module, enable it
3) remove the dummy module from the filesystem
4) check for expected results (error message)
5) if possible, performance profile

repeat same tests as above without patch

stefan.r’s picture

StatusFileSize
new11.94 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 90,982 pass(es).
[ View ]

So I discussed this with @Fabianx on IRC and apparently the concerns in #250 won't pose a problem. The last point would just need feedback from a core committer.

Just a tiny tweak to the last patch in the attachment:

+++ b/core/modules/system/src/Tests/Entity/EntitySchemaTest.php

@@ -28,7 +28,7 @@ class EntitySchemaTest extends EntityUnitTestBase  {
    *
    * @var array
    */
-  public static $modules = array('menu_link');
+  public static $modules = array('menu_link_content');

I'll just delete that altogether, looks like no extra modules are needed in that test anyway.

arosboro’s picture

Patch #189 helped me identify a missing module. Profiling reports a significant decrease in function calls and a savings of 2,000,000 microseconds. (Yes I'm testing a very slow site, but this patch made an improvement none the less)

joseph.olstad’s picture

My dev box is running off of a failover drive (like a human on one kidney) so I'll delay my D8 tests until I get the replacement drive up. I did some preliminary D8 tests but was right in the middle of this when I discovered a hardware problem. Keep up the good work Stefan.r .

jeroen.b’s picture

Just tested this on a fresh install from 8.0.x-dev with the patch from #254 and steps from #253, worked great.
Got the following message in WD:
<em class="placeholder">User warning</em>: The following module is missing from the file system: dummy in <em class="placeholder">drupal_get_filename()</em> (line <em class="placeholder">300</em> of <em class="placeholder">/home/vhosts/jeroen/drupal/d8-patch/core/includes/bootstrap.inc</em>).

stefan.r’s picture

StatusFileSize
new9.3 KB

Interdiff with last RTBC'ed patch for reviewers

Wim Leers’s picture

Assigned:Unassigned» Fabianx
Status:Needs review» Needs work

Only nitpicks. I think it'd be better if e.g. Fabianx reviews this. Assigning.

  1. +++ b/core/includes/bootstrap.inc
    @@ -208,10 +208,23 @@ function config_get_config_directory($type = CONFIG_ACTIVE_DIRECTORY) {
    +  // We use drupal static for the missing records so we can test it.

    s/drupal static/drupal_static()/

  2. +++ b/core/includes/bootstrap.inc
    @@ -208,10 +208,23 @@ function config_get_config_directory($type = CONFIG_ACTIVE_DIRECTORY) {
    +  // Drupal static fast pattern is used as this function may be called often.

    s/Drupal static fast/The drupal_static_fast()/

  3. +++ b/core/modules/system/src/Tests/Bootstrap/GetFilenameUnitTest.php
    @@ -70,7 +70,26 @@ function testDrupalGetFilename() {
    +    // Generate a non-existing module name.
    +    $non_existing_module = uniqid("", TRUE);

    Creative :D

  4. +++ b/core/modules/system/src/Tests/Bootstrap/GetFilenameUnitTest.php
    @@ -70,7 +70,26 @@ function testDrupalGetFilename() {
    +    // Get the missing records static from drupal_get_filename.
    ...
    +    $this->assertTrue($missing['module'][$non_existing_module], 'Searching for an item that does not exist creates a static record in drupal_get_filename.');

    s/drupal_get_filename/drupal_get_filename()/

  5. +++ b/core/modules/system/src/Tests/Bootstrap/GetFilenameUnitTest.php
    @@ -70,7 +70,26 @@ function testDrupalGetFilename() {
    +    // Searching for an item that does not exist creates a static record in drupal_get_filename.

    80 cols, and same remark as above.

Wim Leers’s picture

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new1.51 KB
new11.95 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,428 pass(es).
[ View ]

Status:Needs review» Needs work

The last submitted patch, 261: 1081266-260.patch, failed testing.

Status:Needs work» Needs review

stefan.r queued 261: 1081266-260.patch for re-testing.

Fabianx’s picture

Status:Needs review» Needs work
  1. +++ b/core/modules/system/src/Tests/Common/AttachedAssetsTest.php
    @@ -74,10 +74,20 @@ function testDefault() {
    +    // Set a custom error handler so we can ignore the file not found error.
    +    set_error_handler(function($severity, $message, $file, $line) {
    ...
         $build['#attached']['library'][] = 'unknown/unknown';
         $assets = AttachedAssets::createFromRenderArray($build);
    ...
    +    // Restore the original error handler.
    +    restore_error_handler();

    This should be using an existing module, but a non-existing library.

    That would be a better test anyway and the error_handler handling should be removed here.

  2. +++ b/core/modules/system/src/Tests/Entity/EntitySchemaTest.php
    @@ -24,13 +24,6 @@ class EntitySchemaTest extends EntityUnitTestBase  {
    -   */
    -  public static $modules = array('menu_link');
    -

    It has been a while, so pardon if I re-ask this question:

    Why do we need to remove that line again?

  3. +++ b/core/modules/taxonomy/src/Tests/TermKernelTest.php
    @@ -23,7 +23,7 @@ class TermKernelTest extends KernelTestBase {
    -  public static $modules = array( 'filter', 'taxonomy', 'taxonomy_term', 'text', 'user' );
    +  public static $modules = array( 'filter', 'taxonomy', 'text', 'user' );

    Why do we remove that?

    Does that module not exist?

  4. +++ b/core/modules/views/src/Tests/Plugin/RowEntityTest.php
    @@ -24,7 +24,7 @@ class RowEntityTest extends ViewUnitTestBase {
    -  public static $modules = ['taxonomy', 'text', 'filter', 'field', 'entity', 'system', 'node', 'user'];
    +  public static $modules = ['taxonomy', 'text', 'filter', 'field', 'system', 'node', 'user'];

    Why do we remove that?

    Does that module not exist?

CNW for #1, the rest looks good. I assume core used some non-existing modules in tests. Is that right?

stefan.r’s picture

Status:Needs work» Needs review

re #2, #3, #4: those modules don't exist, so they trigger errors.

stefan.r’s picture

StatusFileSize
new1.16 KB
new11.5 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,695 pass(es).
[ View ]
stefan.r’s picture

Issue summary:View changes

Updated issue summary and added beta evaluation

stefan.r’s picture

Assigned:Fabianx» Unassigned

Status:Needs review» Needs work

The last submitted patch, 266: 1081266-266.patch, failed testing.

Status:Needs work» Needs review

Fabianx queued 266: 1081266-266.patch for re-testing.

Fabianx’s picture

Status:Needs review» Reviewed & tested by the community

Setting to RTBC, this looks great to me now and really needs more feedback by a core committer now.

alexpott’s picture

Status:Reviewed & tested by the community» Needs review
+++ b/core/includes/bootstrap.inc
@@ -208,10 +208,23 @@ function config_get_config_directory($type = CONFIG_ACTIVE_DIRECTORY) {
+  // Return NULL right away if $type or $name is empty.
+  if (empty($type) || empty($name)) {
+    return NULL;
+  }

Should we be triggering an error here if this occurs. It strikes me that this is a bug too and that we'd want to report it.

stefan.r’s picture

I actually don't know that we need to be checking for that there, in any case it seems outside of the scope of this patch.

@joseph.olstad added it in #202 citing #2090115: Don't install a module when its default configuration has unmet dependencies as the reason but I don't really see how that would be passing empty values for those. Maybe he can clarify?

stefan.r’s picture

StatusFileSize
new551 bytes
new11.16 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,714 pass(es), 0 fail(s), and 799 exception(s).
[ View ]

Removing this for now, unless anyone can give any examples where $type/$name would actually be empty. Will ping @joseph.olstad for feedback.

The check would probably be better dealt with in a follow-up issue, along with fixing this at the source instead if there's actually any cases of core sending odd values for those.

Status:Needs review» Needs work

The last submitted patch, 274: 1081266-274.patch, failed testing.

stefan.r’s picture

Ah perfect, seems it already triggers an error anyway, as we have a bug in ExtensionInstallStorage::getAllFolders(), where we look for a file even if drupal_get_profile() == NULL:

<?php
     
if ($this->includeProfile) {
       
// The install profile can override module default configuration. We do
        // this by replacing the config file path from the module/theme with the
        // install profile version if there are any duplicates.
       
$profile_folders = $this->getComponentNames('profile', array(drupal_get_profile()));
       
$this->folders = $profile_folders + $this->folders;
      }
?>
stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new12.17 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/lib/Drupal/Core/Config/ExtensionInstallStorage.php.
[ View ]
new907 bytes

Status:Needs review» Needs work

The last submitted patch, 277: 1081266-277.patch, failed testing.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new363 bytes
new12.13 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,726 pass(es), 0 fail(s), and 730 exception(s).
[ View ]

Status:Needs review» Needs work

The last submitted patch, 279: 1081266-278.patch, failed testing.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new1.23 KB
new13.47 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,705 pass(es), 0 fail(s), and 719 exception(s).
[ View ]

The piece of code in the interdiff doesn't really makes sense to me, why do we pass the type "module" if we're looking for a profile?

stefan.r’s picture

StatusFileSize
new1.48 KB
new13.77 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Invalid PHP syntax in core/lib/Drupal/Core/Config/ConfigInstaller.php.
[ View ]

Adding comment.

Status:Needs review» Needs work

The last submitted patch, 282: 1081266-282.patch, failed testing.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new2.91 KB
new13.77 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,767 pass(es), 0 fail(s), and 11 exception(s).
[ View ]

In any case I don't think #281 is pertinent to this issue.

Opening #2476055: ConfigInstaller searches for profile overrides in module paths for that, let's stick to test failures here :)

Status:Needs review» Needs work

The last submitted patch, 284: 1081266-283.patch, failed testing.

The last submitted patch, 281: 1081266-281.patch, failed testing.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new1.24 KB
new15.23 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,759 pass(es), 0 fail(s), and 4 exception(s).
[ View ]

Status:Needs review» Needs work

The last submitted patch, 287: 1081266-287.patch, failed testing.

stefan.r’s picture

Status:Needs work» Needs review
StatusFileSize
new4.06 KB
new15.11 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 91,788 pass(es).
[ View ]

That took a few tries, let's see if this is green now :)

Interdiff is with the patch that was RTBC'ed in #266

joseph.olstad’s picture

@stefan.r
regarding comments #274, #273 and #272 and #202

I saw you made the spoken changes in #274, looks good to me. My refactoring in #202 kept a regression from #186 because of the flux upstream it was difficult to figure out what part of 186 should remain and what part should be refactored from core commit #40cc6312 for issue #2090115. I imagine that there's been other changes to the d8 dev branch since. Looks like that code snippet spoken of in comment #272 and #273 came in during patch #186 by jeroen.b #124 (see next comment) which may have actually come from another older core commit.

I see #289 passed testing, great work Stefan.r! Stefan.r I know you've done already a lot of work on this but can you please summarize the current status of #289 so everyone else can focus on what is the current status for the D8 patch? I've got a few ideas for test plans but just want to double confirm so that we're all on the same page.

jeroen.b’s picture

Indeed great work @stefan.r!
I think the code snippet from #272 was added in #124, not in #186.

stefan.r’s picture

The patch in 266 was RTBC and the concern was this NULL check, which I am fine with removing. It exposed a few test fails, which have been fixed in the latest patch.

As far as I'm concerned this is ready. Someone just needs to review the interdiff in #289 to make sure the test fail fixes are correct.

jeroen.b’s picture

I think it's good that the empty check was removed.
Returning null on an empty $name or $type is rather a workaround than a bugfix and such errors should be fixed at the source. (like you did)

Can't really tell if your fixes from the interdiff are correct so someone else should look at that.

stefan.r’s picture

Thanks for pointing out that the NULL check came from #124. That confirms it was just about a couple of test fails and should be safe to remove at this point.

@joseph.olstad I wouldn't worry too much about profiling this, the performance penalty is obvious at this point, the current patch doesn't differ functionality-wise from the previous RTBC patch (which had been profiled already).

alexpott’s picture

+++ b/core/lib/Drupal/Core/Config/ConfigInstaller.php
@@ -157,17 +157,23 @@ public function installDefaultConfig($type, $name) {
   public function installOptionalConfig(StorageInterface $storage = NULL, $dependency = []) {
+    $profile = $this->drupalGetProfile();
     if (!$storage) {
       // Search the install profile's optional configuration too.
       $storage = new ExtensionInstallStorage($this->getActiveStorages(StorageInterface::DEFAULT_COLLECTION), InstallStorage::CONFIG_OPTIONAL_DIRECTORY, StorageInterface::DEFAULT_COLLECTION, TRUE);
       // The extension install storage ensures that overrides are used.
       $profile_storage = NULL;
     }
-    else {
+    elseif (isset($profile)) {
       // Creates a profile storage to search for overrides.
-      $profile_install_path = $this->drupalGetPath('module', $this->drupalGetProfile()) . '/' . InstallStorage::CONFIG_OPTIONAL_DIRECTORY;
+      $profile_install_path = $this->drupalGetPath('module', $profile) . '/' . InstallStorage::CONFIG_OPTIONAL_DIRECTORY;
       $profile_storage = new FileStorage($profile_install_path, StorageInterface::DEFAULT_COLLECTION);
     }
+    else {
+      // Profile has not been set yet. For example during the first steps of the
+      // installer or during unit tests.
+      $profile_storage = NULL;
+    }

These changes surprise me - which tests fail for this?

stefan.r’s picture

@alexpott: removing the NULL check causes 799 exceptions altogether now that we have the trigger_error warning: https://qa.drupal.org/pifr/test/1031513

The piece of code you isolated (ConfigInstaller::installOptionalConfig()), makes about all of the tests listed in this other test run fail (other than the QuickEdit and CKEditor tests, which have separate fixes):
https://qa.drupal.org/pifr/test/1031653

stefan.r’s picture

Just to reiterate, we just need someone to review the interdiff in #289 in order to move this issue forward now :)

It's just a few test fixes to make sure we don't do unnecessary calls to drupal_get_filename() if we haven't set a theme/profile yet.