Currently file_scan_directory() call is taking the longest time in terms of Drupal bootstrap performance.
It may take 10-20 seconds on the standard environment just to scan the modules folder over and over again.
See: file_scan_directory() takes about 10 seconds to execute
On the environment with 750 .module files where memcached is present and opcache.enable_cli is enabled, this function may be called over 1500 times (via recursive calls).
See sample profiler stats by running empty command or enabling dummy module e.g. drush en "":

There are 2 calls:
- modules-/^[a-zA-Z_\x7f-\xff][a-zA-Z0-9_\x7f-\xff]*\.module$/-name
- sites/all/modules-/^[a-zA-Z_\x7f-\xff][a-zA-Z0-9_\x7f-\xff]*\.module$/-name
each of them generating 500-1000 calls (depending on the environment and number of modules) which can call PHP functions is_dir, readdir and opendir which are very expensive, since they're I/O calls, secondly they're not always cached, because Drupal uses relative paths, so most likely they're ignored by caching mechanism (like OPCache/APC).
During normal run, you're not expecting modifying module files, placing, removing or renaming files, mostly they're there fixed. The same way when you define some new hook or create template file, you're not expecting to see this file immediately, but it's obvious that you need to clear your caches first.
So idea is to cache the results of file_scan_directory() in order to speed up the bootstrap timings. With memcached it can speed up Drupal by 2x.
Here are the tests performed in VM (within mentioned environment above) before the patch:
1st run (cold run):
[vagrant@html]$ echo flush_all > /dev/tcp/localhost/11211
[vagrant@html]$ time drush ev ""
Drush bootstrap completed in 5s [Mem: 58 of 1024 MB]
Drush operation 'page' completed in 5s. [Mem: 58 of 1024 MB]
Drush operation 'ev ' completed in 0s. [Mem: 58 of 1024 MB]
real 0m5.962s
user 0m1.858s
sys 0m2.032s
[vagrant@html]$ time drush en ""
Drush bootstrap completed in 5s [Mem: 58 of 1024 MB]
There were no extensions that could be enabled.
Drush operation 'page' completed in 17s. [Mem: 73 of 1024 MB]
Drush operation 'en ' completed in 0s. [Mem: 73 of 1024 MB]
real 0m17.357s
user 0m3.035s
sys 0m7.479s
2nd run (warm run):
[vagrant@html]$ time drush ev ""
Drush bootstrap completed in 3s [Mem: 26 of 1024 MB]
Drush operation 'page' completed in 3s. [Mem: 26 of 1024 MB]
Drush operation 'ev ' completed in 0s. [Mem: 26 of 1024 MB]
real 0m3.486s
user 0m0.852s
sys 0m1.496s
[vagrant@html]$ time drush en ""
Drush bootstrap completed in 3s [Mem: 26 of 1024 MB]
There were no extensions that could be enabled.
Drush operation 'page' completed in 14s. [Mem: 41 of 1024 MB]
Drush operation 'en ' completed in 0s. [Mem: 41 of 1024 MB]
real 0m14.966s
user 0m2.282s
sys 0m6.782s
With the patch (warm):
[vagrant@html]$ time drush ev ""
Drush bootstrap completed in 3s [Mem: 26 of 1024 MB]
Drush operation 'page' completed in 3s. [Mem: 26 of 1024 MB]
Drush operation 'ev ' completed in 0s. [Mem: 26 of 1024 MB]
real 0m3.208s
user 0m0.847s
sys 0m1.375s
[vagrant@html]$ time drush en ""
Drush bootstrap completed in 3s [Mem: 26 of 1024 MB]
There were no extensions that could be enabled.
Drush operation 'page' completed in 15s. [Mem: 41 of 1024 MB]
Drush operation 'en ' completed in 0s. [Mem: 41 of 1024 MB]
real 0m15.643s
user 0m2.262s
sys 0m6.975s
[vagrant@html]$ time drush en ""
Drush bootstrap completed in 3s [Mem: 26 of 1024 MB]
There were no extensions that could be enabled.
Drush operation 'page' completed in 7s. [Mem: 41 of 1024 MB]
Drush operation 'en ' completed in 0s. [Mem: 41 of 1024 MB]
real 0m8.025s
user 0m2.119s
sys 0m3.189s
During run two cached objects are 19488 & 153701 bytes long ( print("Len: " . strlen(serialize($files_to_add)) . "\n"); ).
Patch is probably not useful for running empty command, but there are some cases that this function is called quite often, e.g. on fra (reverting all the features via drush), where each revert invoking bootstrap takes 10-20 seconds, so for 200 features it may take over 2000 seconds (> 30 mins or even hours).
| Comment | File | Size | Author |
|---|---|---|---|
| #4 | file_scan_directory-caching-2710289.patch | 893 bytes | kenorb |
| Screen Shot 2016-04-20 at 18.26.17.png | 74.42 KB | kenorb |
Comments
Comment #2
kenorb commentedComment #3
kenorb commentedAnother test with 'cc all', with the patch:
Without the patch:
Which gives around 13 seconds difference as it seems the file_scan_directory was called 6 times during one 'cc all' command.
Comment #4
kenorb commentedRe-uploading since tests didn't run.
Comment #6
kenorb commentedThe CI build fails with:
This is potential drush bug. Reported at: GH-2143 (PR: GH-2144).