ctools_plugin_load_includes() can set cache on every request

Note that in Panels 2 there was a bug that caused this to be called a lot more often than necessary. We've benched this and not found it to be that bad once we dealt with that bug -- would you verify that there's still a savings by doing this?

I don't remember, it's been a long time. Your metrics are interesting, though. I'll have to check this out a little.

I’ve tried this patch out on a couple of my sites, and it does seem to give a 5-10% improvement on simple pages. I’ve tried to see what it looks like when profiling with XDebug. You can check out the profiling data – in this case it cuts off about 300 ms, but since there’s so much overhead involved with running XDebug, that might not be all that accurate.

Wow. I knew that those filesystem scans were expensive, but that's a surprise.

I'm 100% in support of caching the filesystem contents. We may want to consider if/how we let this change the way we cache plugin definitions, as well.

My benchmark on local pc. Frontpage is a panel. Page cache is disabled.
Without patch:

crea@abyss:/tmp/drupal 8 apr$ sudo ab -n1000 -c1 -k http://dev.example.com/
This is ApacheBench, Version 2.3 <$Revision: 655654 $>                     
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/   
Licensed to The Apache Software Foundation, http://www.apache.org/         

Benchmarking dev.example.com (be patient)
..
Finished 1000 requests                   

Server Software:        nginx/0.6.32
Server Hostname:        dev.example.com
Server Port:            80             

Document Path:          /
Document Length:        10002 bytes

Concurrency Level:      1
Time taken for tests:   110.316 seconds
Complete requests:      1000           
Failed requests:        0              
Write errors:           0              
Keep-Alive requests:    0              
Total transferred:      10484000 bytes 
HTML transferred:       10002000 bytes 
Requests per second:    9.06 [#/sec] (mean)
Time per request:       110.316 [ms] (mean)
Time per request:       110.316 [ms] (mean, across all concurrent requests)
Transfer rate:          92.81 [Kbytes/sec] received                        

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   102  110  22.2    107     771
Waiting:       90   98  16.5     95     571
Total:        102  110  22.2    108     771

Percentage of the requests served within a certain time (ms)
  50%    108                                                
  66%    109                                                
  75%    111                                                
  80%    113                                                
  90%    118                                                
  95%    121                                                
  98%    127                                                
  99%    144                                                
 100%    771 (longest request)

With patch:

crea@abyss:/tmp/drupal 8 apr$ sudo ab -n1000 -c1 -k http://dev.example.com/
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking dev.example.com (be patient)
..
Finished 1000 requests

Server Software:        nginx/0.6.32
Server Hostname:        dev.example.com
Server Port:            80

Document Path:          /
Document Length:        10002 bytes

Concurrency Level:      1
Time taken for tests:   103.571 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Keep-Alive requests:    0
Total transferred:      10484000 bytes
HTML transferred:       10002000 bytes
Requests per second:    9.66 [#/sec] (mean)
Time per request:       103.571 [ms] (mean)
Time per request:       103.571 [ms] (mean, across all concurrent requests)
Transfer rate:          98.85 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:    95  103  11.1    101     385
Waiting:       83   91  10.7     89     373
Total:         95  104  11.1    101     386

Percentage of the requests served within a certain time (ms)
  50%    101
  66%    104
  75%    106
  80%    107
  90%    110
  95%    113
  98%    121
  99%    133
 100%    386 (longest request)

We could always respond to hook_menu to clean that cache; menu rebuild happens more often than module changes but it's not that common of an occurrence and and it usually coincides with system level changes like this. We'd have to very carefully document the need to clear cache when adding new .inc files.

So with some additional benchmarks...yeah, let's just say this patch is essential. Though right now I think c9's approach may not go far enough. Upping this to critical, and I'll be coming back to it soon.

Just helped someone debug performance issues on a VPS, and this function was responsible for 20+% of page execution time, more than db_query(). However the patch doesn't apply.

Patch applied fine for me - were you applying the patch against a release or dev, catch?

I've committed this to DRUPAL-6--1 for the present moment, but in the future will be taking additional steps: instead of doing the directory scan on demand we'll do it all at once, akin to menu or registry rebuild. I'm not doing it now because it will require the addition of a new hook that plugin-creating modules will have to implement in order to inform the plugin system that it provides the plugin. We can be cleaner if we do it all at once - use a semaphore, minimize the number of write queries, and have slightly less logic overall. Being that the performance difference will probably be small, and it would require existing modules to go back in and implement yet _another_ hook to provide plugins, I'm probably going to want to wait on it for the D7 branch, as we'll be needing that sort of hook for our registry integration, anyway.

Oh, this is great. Maybe it is enough to document when it is adviced to clear this cache entry. Though, where?

Ok, I have partially reverted (just the caching portion) of this patch. Major major problems with this include:

1) whitescreens when modules are disabled but the plugin cache still contains the old plugins.
2) Even when trying to account for that, I was having timing issues between resetting the cache and hook_theme(). To duplicate: With this patch on, set up a panel page with at least one style using stylizer. Disable panels stylizer. Now visit your page. The theme() function is still registered. I fiddled with this for awhile, but it's a thorny problem.

In plugins.inc line 421:

function ctools_plugin_load_includes($info, $filename = NULL) {
  // Keep a static array so we don't hit file_scan_directory more than necessary.
  $all_files = &drupal_static(__FUNCTION__, array());

  // store static of plugin arrays for reference because they can't be reincluded.
  static $plugin_arrays = array();

  // If we're being asked for all plugins of a type, skip any caching
  // we may have done because this is an admin task and it's ok to
  // spend the extra time.
  if (!isset($filename)) {
    $all_files[$info['module']][$info['type']] = NULL;
  }

  if (!isset($all_files[$info['module']][$info['type']])) {
    // If a filename was set, we will try to load our list of files from
    // cache. This is considered normal operation and we try to reduce
    // the time spent finding files.
    if (isset($filename)) {
      $cache = cache_get("ctools_plugin_files:$info[module]:$info[type]");
      if ($cache) {
        $all_files[$info['module']][$info['type']] = $cache->data;
      }
    }

    if (!isset($all_files[$info['module']][$info['type']])) {
      $all_files[$info['module']][$info['type']] = array();
      // Load all our plugins.
      $directories = ctools_plugin_get_directories($info);
      $extension = empty($info['info file']) ? $info['extension'] : 'info';

      foreach ($directories as $module => $path) {
        $all_files[$info['module']][$info['type']][$module] = file_scan_directory($path, '/\.' . $extension . '$/', array('key' => 'name'));
      }

      cache_set("ctools_plugin_files:$info[module]:$info[type]", $all_files[$info['module']][$info['type']]);
    }
  }

Called in plugins.inc line 278:

$plugins[$module][$type] = array_merge($plugins[$module][$type], ctools_plugin_load_includes($info[$module][$type]));

With no $filename parameter. This is being called in every page by:

• Context (multiple time for the same data)
• Search API
• Facet API (multiple time)

This on the 7.x dev version (and also stable). This code triggers a cache_set() on almost every call. I have an average 3 to 5 cache_set() calls per page site wide, thus using database backend implies db_merge(), multiple queries and a transaction.

This must be fixed.

yeah, i thought this had gotten attention since we looked at it two years ago. clearly not. i'll try to take a poke at the thorny problems. i've got the feeling it's gonna be one of those brute force solutions.

Thanks, small hint: when you look at the ctools_plugin_load_includes() function inner code, the algorithm is not symetric: cache_get() and cache_set() are not always in the same code path, which implies the extra useless calls being done multiple time.

The cache_set() are always triggered in case there is no $filename parameter given, problem is that some modules such as context will trigger this particular piece of algorithm in normal production sites execution flow.

Here is an ugly patch attached, which seems to fix this.

Switching to needs review, but in real life it needs work, it's only to wake this issue. EDIT: Patch won't pass, did that with SVN (sorry, no GIT at work).

yeah sorry, i just moved across the city, and my life is just now becoming sane again. this is high on my priority list...though it will be knotty.

You don't need to apologize! I am providing a patch to be some kind of help myself too.

Regarding this patch, it actually removes a lot of logic inside the function that seems to be tied to the fact that only in admin plugins lists will be loaded (which is not the case here because some other modules are using it on normal site runtime). I think this logic should be removed as in my patch, any simplification here would be welcome: the CTools plugin handling is really complex code that probably could be deeply simplified, this is a tiny piece of dust removed IMHO.

the help is certainly appreciated :)

it is complex code, to be sure. and while some simplifications probably are possible, i'm not sure how much really can be pulled out. much of the indirection is dealing with the varying methods for discovery & plugin definition listing, as well as performing processing/normalization of plugin type definitions as well as plugin definitions. and a lot of other contracts which, while they could be simplified in a full revamping of the system, can't really be done without potentially breaking a lot of plugins out there now. and that revamp is 8.x, anyway - perhaps once that's more stable, we'll start making modifications to ctools' plugins in order to be more in line with that system, as that'll be a more justifiable API shift.

whenever i revisit ctools' plugin system, i tend to start with the belief that a lot could be simplified, but gradually remind myself of the reason why most of what's there is there. but hey...patches welcome :)

I just debugged this too and had the same idea as the patch in #19.
Patch re-rolled and added cache flush to hook_modules_enabled / hook_modules_disabled.
I think this is very reasonable since it's not at all an "admin task" to call ctools_plugin_load_includes() without a filename - e.g. panelizer does that on runtime.

#24 approach seems more predictive and simple, I like this patch.

This *needs* to be commited. #24 patch is working great.

Still not moving forward with this patch ?

Also it's not just the file system scan, I just found this writing the cache item on every request on a client site, moving to bug report. Patch looks great.

Patch is working great for me and according to xhprof has sped up a few sections considerably :)

If catch approves, I approve. Code looks good form a review standpoint and my testing hasn't shown any regressions. Committed.

Just mentioning there was a slight bug introduced with this patch in relation to menu block / form state as it includes "module_load_include('inc', 'menu_block', 'menu_block.admin')" on the fly in plugins/menu_tree.inc and with the new caching system this file never gets loaded. I discussed this issue over at: #2407951: Regression with ctools_plugin_load_includes() can set cache on every request.

I'm not sure I'd agree with @stylus that this is a "slight bug" - it causes a fatal PHP error when using Menu Block because it can't locate some #element_validate functions used in it's form. This might not be the only content type that is broken and I can't think of a way to fix it in Menu Block without just always loading menu_block.admin.inc on every request...

We can continue working on this in #2407951: Regression with ctools_plugin_load_includes() can set cache on every request, though!

Or actually, I take that back - I can think of a way to fix it in Menu Block that doesn't load on every request: we can do the include at the top-level of the content type plugin .inc file. I guess that'll work! Nevermind - it is a "slight bug". :-)

Yay @dsnopek your so awesome, thanks for providing the fix!