New plugin system causes significant slowdowns

[ewinslow]

In my rudimentary tests, I found that plugin loading time is where the bulk of Elgg startup time occurs. When plugins are loaded they do a lot of parsing, self-validation, loading manifests, etc. There's no reason to do this over and over on every page load, since the results are the same regardless of viewtype, logged in user, etc.

On my localhost, elgg_get_plugins('active') was taking ~3.25 seconds of total execution time without caching (haven't figured out exactly why it was taking so long in the first place). With caching it was only eating up around ~200ms of total execution time.

[brettp]

It takes a long time because of validation. It checks that the plugin package is valid, then parses the manifest, then checks the deps. This is a lot. I was planning to remove checking manifest and deps on normal page loads and only doing it on the plugin admin page. A question is how protective do we want to be against physically changed files between caches? If a user activates oauth_api and twitter_api, then deletes oauth_api, do we let Twitter cause a WSOD or do we deactivate it on boot?

[cash]

200 ms to load plugins still seems like a lot of time.

If the twitter plugin is well written, it should have its own runtime check. A call to function_exists() should be cheap compared to loading all the manifests.

[ewinslow]

@Cash, The relative numbers here are the most interesting, I think, since absolute numbers will always vary based on configuration/hardware. In my tests the bulk of the time is spent on including and/or parsing files. If there is some setting that I can change that would help optimize this process with XAMPP, advice would certainly be welcome.

@Brett, And actually, validating each plugin wasn't taking all that long on my machine. $plugin->isValid() checks took somewhere around ~1ms per plugin. Now, this adds up to something noticeable when you have, say, 70 plugins installed and activated (as we do), but it certainly wasn't the bottleneck. By far the most time was spent on including/parsing. The core lib was taking 1.5 seconds, loading plugins still takes 2.2 seconds, and generating the html is taking anywhere between 5-15 seconds depending on the page.

It's rather embarassing to have these numbers out there... this is a brand new computer (~6 months old). I really don't know why it's having so much trouble. But again, it's the relative numbers that I'm trying to emphasize in this conversation...

[cash]

I have also noticed on my almost new laptop that Elgg has become quite slow in the last few months. Evan, do you have numbers for 1.7 using your computer?

[brettp]

I've been testing plugin loading using the CSS page to avoid HTML generation. Here's my results:

• elgg_load_plugins() accounts for ~75% of full load time.
• ElggPlugin->start() accounts for ~50% (relative to elgg_load_plugins()) and most of that is calling back to elgg_load_plugins() in the canActivate().
• Loading and parsing the manifest takes ~10% of full load time.

I'm on a SSD drive, so disk reads are significantly faster than standard HD media. The time it takes to include will be skewed for me, but parsing should be about the same.

If the twitter plugin is well written, it should have its own runtime check. A call to function_exists() should be cheap
compared to loading all the manifests.

Part of the reason for introducing deps was to prevent having to do exactly this or using is_plugin_enabled().

I'll look into not loading manifests unless on the admin page. Off hand I can't think of any gotchas with this except that we can't autodisable plugins that have unmet deps

[cash]

Here are my stats. Same computer. Same database. Same plugins (21 of the bundled plugins). No apc

Elgg 1.7.8

• plugins: 0.04 seconds
• start.php: 0.14 seconds

Elgg trunk [svn:9001]

• plugins: 0.10 seconds
• start.php: 0.18 seconds

The jump in time for loading plugins is very significant if we're going to start Ajaxifying Elgg.

One more point: when I turned on apc the non-plugin time dropped in half but the plugin load time stayed constant.

[cash]

Made a mistake in my profiling. I was not caching the views. You can take .02 off all those numbers which makes the percentage increase for the plugin code even worse.

My top functions for 1.8 are:

xml_to_object	8%
add_translation	4%
elgg_get_file_list	4%
php::mysql_query	3%
ElggPluginManifest->getConflicts	3%
ElggPlugin->isValid	3%
elgg_query_runner	3%
ElggPlugin->get	3%
ElggPluginPackage->checkDependencies	2%
ElggPluginManifest->construct	2%
elgg_get_plugins	2%

Those are all self costs. Most of the next 10 are also related to the plugin system. These number for evaluating start.php.

[brettp]

The plan for the plugin speed up:

• Cache active plugin list to disk. (A static var cache decreased
• Recache on admin area plugin page

[brettp]

(In [svn:9030]) Refs #3362. Plugins don't check deps upon boot. Made package and manifest private properties of ElggPlugin and added ->getPackage() and ->getManifest().

[brettp]

Ignore the text in comment #8. That is not the plan.

[brettp]

(In [svn:9031]) Refs #3362. Removed use of $show_bad in elgg_get_plugins().

[cash]

Do we need to profile this to test that it is fixed or are there changes planned?

[brettp]

I profiled it earlier but it could use a second opinion. My changes fixed the worst offenders for most page loads, but there is still slowdown on the plugins admin page. I think that's acceptable, though.