Typo causes extra query every page load

There was already a todo above that line of code, but i would not have thought this to cause an additional query.

In fact I removed the line altogether as it din't work, couldn't work (even if correctly spelled, it would try to include image_overlay.inc.inc) and so was apparently superfluous in the first place.

Fixed and committed. Thanks for reporting.

Be ware: in the current Drupal version, this causes even more problems. Drupal does a recursive file_scan_directory now to find the module (I think since 7.33/7.34) when you do something like this. The change that caused this:

@@ -852,7 +861,7 @@ function drupal_get_filename($type, $name, $filename = NULL) {
try {
  if (function_exists('db_query')) {
    $file = db_query("SELECT filename FROM {system} WHERE name = :name AND type = :type", array(':name' => $name, ':type' => $type))->fetchField();
-   if (file_exists(DRUPAL_ROOT . '/' . $file)) {
+   if ($file !== FALSE && file_exists(DRUPAL_ROOT . '/' . $file)) {
        $files[$type][$name] = $file;
      }
}

In bootstrap.inc

Be ware: in the current Drupal version, this causes even more problems.

Just to clarify, perhaps those includes need changing to require_once as the docs says.

...Do not use this function in a global context since it requires Drupal to be fully bootstrapped, use require_once DRUPAL_ROOT . '/path/file' instead.

Cannot use require_once DRUPAL_ROOT . '/path/file' as the module could be installed in various places.
I think it's odd that docs would advise AWAY from using module_load_include!

... "in a global context" ....
Yeah OK, we should not be doing that at file context, that's pretty true.

module_load_include() shouldn't be outside of the function call anyway. I think this line should just be removed and added within any function that needs methods from that file.

The bug is fixed, so resetting the status. If you want us to change the code to follow advice, it becomes a (new) feature request. In general it is indeed advised to use include/require_once for your own files whenever possible, see e.g. the discussion in #1308152: Add stream wrappers to access extension files, comment #202 and further. It is debatable whether this is an "own file" as the module_load_include takes place in a submodule and in theory can thus be moved around away from the main module of this project.

Created a working patch with the line removed.

Cannot use require_once DRUPAL_ROOT . '/path/file' as the module could be installed in various places.

Then you should use require_once dirname(__FILE__) . '/image_overlay.inc';

@mmrares - Thanks for the quick fix in a pinch.

Thanks as well for the patch, this fixed my site – I was encountering the problem several times already an refrained from updating.

It was hard to find info about this– maybe a warning on the project page on currently using the dev version or applying this patch should lead more people to the right clue.

Not sure what could be done to provide more info in a reasonable way.

Anyone choosing a -dev installation knows it's implicitly unstable.

Any stable release number of every single module offers improvements like small bugfixes or performance improvements on the version that came before. That's what additional releases are for.

The vast majority of users that may be potentially affected by this fringe issue (that's only a tiny performance blip when an image is being regenerated) would not come looking at the project page for insight, but may notice the status report alerting them to an updated minor version update - which is what happened when the last release was rolled.

It may be that you found this typo more serious than anyone else did, but putting a full CHANGELOG on each modules project page wouldn't really help folk much. Every bugfix is relevant or important to someone - but elevating them all to project page announcements would just be heaps of noise.

The only remaining 'fix' for the solution being hard to find is the one I encourage a lot in documentation maintenance:
Please add the phrases you used when searching for this issue - into this thread so that anyone else that was searching using the same thought process as you next time will have a chance of finding this solution quicker. I don't know what keywords you used that failed, I can't even describe the symptoms that you identified to get here, but you can put them here to help the next searcher! That may help!

"that's only a tiny performance blip when an image is being regenerated"

I don't think that's true. The code was at the top of the module (outside any hook), so the file lookup would be triggered on every page load.

That sounds possible, yep, assuming you have turned caching off, I guess.
But I'm curious about how many % of the entire Drupal bootstrap process this one failing-operation line could be profiled to affect. How much actual difference did anyone measure in a stack trace? How much heavier is it than any other line of PHP that's sorta unnecessary or redundant? Genuine profiling stacktrace numbers would be interesting to see.

I would still call it a "tiny performance blip" that I don't think my system could even measure. It's good to clean up, for sure, but I'd think the effect it had was infinitesimal. If you have benchmarks that demonstrate otherwise, please share.

Eh, no... Are you on the latest Drupal?
The following code was executed on every page run:

$matches = drupal_system_listing("/^" . DRUPAL_PHP_FUNCTION_PATTERN . "\.$extension$/", $dir, 'name', 0);
foreach ($matches as $matched_name => $file) {
  $files[$type][$matched_name] = $file->uri;
}

Which in return executes a file_scan_directory, which scans the Drupal installation for the missing module, on every page load.

Here is my blog about it:
http://www.vdmi.nl/blog/i-went-drupal-733-and-all-i-got-was-slow-site

The relevant issue here:
https://www.drupal.org/node/1081266

@dman I think this would be more significant that you make out.

module_load_include() with an invalid path on every page request is going to result in a drupal_get_path(), dirname(), is_file(), file_exists(), db_query() and a few function_exists() calls just to note a few of the methods I can see by looking at the code.

Yeah, stuff gets cached but I think that code path would certainly be measurable.

Also, the file should have been included with require_once as mentioned in: https://www.drupal.org/node/2166715#comment-9388385 That's the recommended way when it's your own file outside of a function call.

Interesting, and good, blog post. Thanks!

So although this particular typo was sorted out (in -dev) January last year, it seems there were a few weeks in November last year when some folk who upgraded to the latest code could have found the file_scan_directory running greedier than usual. It wasn't until the end of November last year for the imagecache_actions stable release to be rolled for public use, at which point I guess the problem would be marked 'fixed'.

I was imagining the 'could not load the named file' issue would be only as expensive as the usual PHP include() failure. Which is inefficient as it bubbles through the error stack, but hardly a performance killer in itself.
If, as the blog implies, the 7.33 change produced measurable performance changes, then that would have been annoying - back in November. Dang.
Any numbers on that?

I don't have any numbers on that, sorry. Some of our sites became unreachable/very slow after the upgrade.
The actual impact depends on the amount of modules/directories/files.

This sounds like it's worth looking into - just for curiosity. I've got some profiling set up today on a real-world, good-sized site (about 100 contribs). Local dev only, so numbers are for comparison only, and caching introduces a bit of variety. (doing it by hand, so I didn't do multiple runs to get an average, as I'd normally expect to do)

Drupal 7.34, standard primed caching,

no imagecache_actions, 2.710s .
244 calls to module_load_include() (55ms, 2% runtime) 12 calls to file_scan_directory()

imagecache_actions-7.x-1.4 with imagecache_canvasactions on. 3.764s.
251 calls to module_load_include() (885ms 25%), 982 calls to file_scan_directory()
- yes, that is really measurable! Sheesh!

imagecache_actions-7.x-1.5 with imagecache_canvasactions on. 2.732s.
250 calls to module_load_include(), 12 calls to file_scan_directory()
- back to normal.

So yeah, it sure looks like sites that were updated in early November, but not since a couple of weeks later, would have seen some pain there.
This is not just a PHP local file load failure performance "blip", that 7.33 update really does have a nasty effect.

WTF? This problem was reported on January 3, 2014 at 7:47pm and fixed and committed (to the dev version) 47 minutes later. Apparently, after the release of D7.33 the problem (by then already solved for a good 10 months) became much worse in terms of performance degradation. This aggravation was reported on November 27, 2014, so 2 days later we released a new stable version 7.x-1.5. I would call that (extremely) good community behavior form our side. And now, 2.5 months after that stable release we still have people that come whining here???

BTW: we are indeed not going to report on the project page on errors that are solved in the current stable release. We carefully keep our changelog text file up to date and our commit messages always contain an issue number and a short description.

@dman, @fietserwin:
Sorry – I didn't mean to stir up so much trouble – I was under the impression the actual fix wouldn't be in the last stable release, as I had already updated every module via drush.

The first time we encountered slower loading times in November we couldn't correlate it to the update and re-rolled a backup. Afterwards, I encountered the problem on another site I thought we had fully updated.

So sorry again for misunderstanding the state of this fix – and thanks for your good work on this module!