Problem/Motivation

This is a child issue of #2308683: [meta] Create a 'Profiling' install profile, for testbot-powered simple profiling and easier local profiling. Please read the IS there first!

In order to determine a baseline of Drupal 8 performance, tracked over time to ensure no serious regressions, we need to develop reproduceable scenarios/performance targets. This gives people new to profiling have somewhere to start looking, and we can also eventually have an install profile with default content to look at.

The idea of this list is not to simulate a 'real' site, but to look at both fastest, slowest and 'average' core scenarios that are easy to reproduce.

Proposed resolution

The following are scenarios that have been agreed upon by various performance-savvy Drupal core contributors, including catch, Wim Leers, dawehner, Fabianx, etc.

Between scenarios

Do drush cr, or alternatively, do a clean install.

Each scenario requires two tests:

1. Apply index.php.diff and check memory usage for the tested requests.

2. Profile with xhprof and check number of function calls + database queries (PDO::execute() will do).

Scenario A: "Install a module"

(This tests the worst case scenario, because it invalidates all caches, and is therefore very expensive. We want to make sure that Drupal 8 site builders can install some amount of modules without exceeding the minimum memory limit that Drupal 8 requires during installation.) Not for this scenario, and only this one opcode caching should be disabled (APCu can be left enabled though).

  1. Disable opcode caching
  2. Install Standard
  3. Log in as user/1
  4. Go to admin/modules
  5. Select actions module and submit the form.
  6. Record stats for the last two requests (A1 and A2) — i.e. the form submit and the subsequent rendering of the form.

(Related: #2494987: [meta-6] Reduce cold cache memory requirements.)

Scenario B: "Empty front page as an anonymous user with page caching disabled and warm caches"

Skip memory usage for this one - we know it'll be low, and the index.php patch would have to be adapted specifically for this scenario.

  1. Install Standard (stay logged out).
  2. drush pm-uninstall page_cache
  3. Refresh front page twice
  4. Refresh once more — check profiling data for this request (B1)

Scenario C: "Empty front page as an anonymous user with page caching enabled and warm caches"

(This tests how fast the page cache is.)

  1. Install Standard (stay logged out)
  2. Refresh front page twice
  3. Refresh once more - check profiling data for this request (C1)

Scenario D: "Authenticated user"

  1. Install standard
  2. Create one 'page' node with title test and path alias test
  3. Create on 'article' node with title 'test2' and path alias 'test2'
  4. Create user 2 u: test p: test, no extra roles
  5. Log out, then back in again with test/test
  6. drush cr
  7. Visit front page (D1)
  8. Visit front page again (D2)
  9. Visit node/1 (the page node) (D3)
  10. Visit node/1 again (D4)
  11. Visit node/2 (the article node with 50 comments) (D5)
  12. Visit node/2 again (D6)

D1 is cold cache performance.
D2 is warm cache performance
D3 is cool cache
D4 is warm cache
D5 is cool cache
D6 is warm cache

Scenario E: "Authenticated user"

  1. Install standard and log in as user 2
  2. (The install profile will have created one page node and an article node with 50 comments. Each should have an alias. Both should be promoted to the front page. Possibly add additional nodes for the front page view so that it is full with a pager)
  3. drush cr
  4. Visit front page (E1)
  5. Visit front page again (E2)
  6. Visit node/1 (the page node) (E3)
  7. Visit node/1 again (E4)
  8. Visit node/2 (the article node with 50 comments) (E5)
  9. Visit node/2 again (E6)

E1 is cold cache performance.
E2 is warm cache performance
E3 is cool cache
E4 is warm cache
E5 is cool cache
E6 is warm cache

Remaining tasks

We need to be able to reliably reproduce approximately the same numbers of determine the number of function calls, number of db queries, and peak memory usage for these scenarios.

So far this has been attempted by @catch in #31; @dawehner in #34; @znerol in #35, and @cthos in #56 and #69, but each got different results.

@cthos (with the help of @Fabianx) created a set of automated scripts at https://github.com/cthos/d8-perf-casper that attempt to automate the scenario testing. We need 2-4 people to independently try to use the scripts and get approximately the same results.

Runs should be tracked in the spreadsheet at https://docs.google.com/spreadsheets/d/1_XbRrwEcqiLyDrWh3zTmOoVUaCzJ_oLM...

CommentFileSizeAuthor
#29 index.php_.diff279 bytescatch
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

catch’s picture

Issue summary: View changes
Wim Leers’s picture

catch’s picture

Issue summary: View changes
Wim Leers’s picture

I'm missing "authenticated user" scenarios?

catch’s picture

Yes. Need to add those.

And also would be good to add a content listing scenario, but we can't easily standardize that without an install profile.

Wim Leers’s picture

So why not add a "Profiling" install profile? i.e. #2308683: [meta] Create a 'Profiling' install profile, for testbot-powered simple profiling and easier local profiling. I thought this was the issue to discuss the scenarios, and then add them to core via a separate install profile in #2308683: [meta] Create a 'Profiling' install profile, for testbot-powered simple profiling and easier local profiling?

catch’s picture

@Wim sorry yes that's exactly what I meant :)

Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Issue summary: View changes
Wim Leers’s picture

Proposed plan of attack. (From a call with Moshe, effulgentsia, catch and Tyler Littlefield.)

  1. Put the scenarios in the IS into core in #2308683: [meta] Create a 'Profiling' install profile, for testbot-powered simple profiling and easier local profiling.
  2. We should automate metrics that we can automate, to get feedback *while* we're working on core.
    We'll add metrics one by one, to ensure they don't increase beyond the recorded number, starting with:
    1. peak mem: number+5%
    2. DB queries (if possible: distinguish between reads and inserts): exact number
    3. initialized services: exact number
  3. The number of function calls, we cannot automate. So, we should manually record the number of function calls in the various scenarios today, and then compare before tagging the first RC. (For RC, it should simply not exceed the number as of today.)
Wim Leers’s picture

In fact, it makes more sense to do #20.1 here #20.2.1 (i.e. only peak mem), and make #2308683: [meta] Create a 'Profiling' install profile, for testbot-powered simple profiling and easier local profiling the parent.

It'll make most sense to start from the patch in #2308683-1: [meta] Create a 'Profiling' install profile, for testbot-powered simple profiling and easier local profiling, remove the unwanted-for-now parts, and update it to apply to D8 HEAD.

I think Tyler Littlefield is going to take a stab at this one.

catch’s picture

So, we should manually record the number of function calls in the various scenarios today, and then compare before tagging the first RC. (For RC, it should simply not exceed the number as of today.)

I think I'd probably want to modify this slightly to 'with critical performance patches applied' - just because if we don't do that, then we could in theory re-introduce the equivalent of several critical performance issues without noticing.

Wim Leers’s picture

catch’s picture

And after talking to alexpott and Fabianx, another modification.

We should profile and document the following:
HEAD
HEAD + critical performance patches applied.

Then for each scenario, consider whether we want to additionally set a lower threshold (to take into account there might be 20 actionable major performance issues in the queue that significantly improve the situation). So for example page/1 with warm caches might come out at 22,000 function calls, but we might have 10 issues that save 500 function calls each which are all pretty close. If we set a target of 19,000 function calls, that ensures we're actually making progress in the time up to release candidate, not just treading water as we exchange improvements for regressions elsewhere.

Wim Leers’s picture

We discussed #24 in IRC, +1.

catch’s picture

Issue summary: View changes
catch’s picture

Issue summary: View changes
catch’s picture

Issue summary: View changes
catch’s picture

FileSize
279 bytes

Attaching the patch I use for memory readings.

catch’s picture

Issue summary: View changes
catch’s picture

Issue summary: View changes

Started a google doc at https://docs.google.com/spreadsheets/d/1iTFR2TVP-9961RUQ4of-N7jZLTOtfwf3...

It would be great for someone to run the scenarios I've done so far following the steps and confirm they get the same numbers. Memory usage will vary slightly but function calls and database queries should be absolute.

catch’s picture

Issue summary: View changes
catch’s picture

Issue summary: View changes

Added a simplified version of scenario D, and moved the old scenario D to scenario E.

This is because scenario E is impossible to reproduce without either an install profile or shared database dump to work from, so it's going to be left out of the spreadsheet until we sort one of those out (too much content to add).

catch’s picture

Title: Add a 'Profiling' install profile + test coverage to automatically profile 4 scenarios » Create standardized core profiling scenarios and start tracking metrics for them
catch’s picture

Issue summary: View changes
catch’s picture

Issue summary: View changes
giorgio79’s picture

If we would have either

scripts for these scenarios, testing could further be automated for local testing.
The script could even collect the memory and function call usage if these stats are outputted by webprofiles or devel on the page. Furthermore, actual browser memory cpu and memory usage could be tracked for client side performance. :)

catch’s picture

Status: Active » Needs review

Bumping this to CNR - the scenarios and my baseline profiling need review/confirmation.

@giorgio79 #2308683: [meta] Create a 'Profiling' install profile, for testbot-powered simple profiling and easier local profiling is dealing with the first steps of automating this.

Status: Needs review » Needs work

The last submitted patch, 29: index.php_.diff, failed testing.

effulgentsia’s picture

Priority: Major » Critical
Issue tags: +blocker

Raising this to critical, since it's a blocker for performing the "profile key scenarios to ensure no regressions" checklist item in #2485119: [meta] The Drupal 8.0.0-rc1 Release Checklist.

effulgentsia’s picture

Status: Needs work » Needs review

What needs review here is #31 / #38, not the patch, so back to NR.

Fabianx’s picture

Title: Create standardized core profiling scenarios and start tracking metrics for them » [no patch] Create standardized core profiling scenarios and start tracking metrics for them
dawehner’s picture

I tried to gave it a try but I reached much higher numbers, so I think something obvious is wrong.
I filed it out so far:

Scenario A1
Function calls 1405556  
Memory 57.5
PDOStatement::execute 1157
Scenario A2
Function calls 578499
Memory 55.5
PDOStatement::execute 522
Scenario B1
Function calls 26,403
Memory 14.83
PDOStatement::execute 47
Scenario C1
Function calls
Memory
PDOStatement::execute
Scenario D1
Function calls
Memory
PDOStatement::execute

I thought for a bit, that the profiling from catch did not counted internal PHP function calls, but this brought down B1 to 16k, so I think this was not the problem.
Maybe someone else could try to reproduce it.

xjm’s picture

Issue tags: +D8 Accelerate London
znerol’s picture

I'm trying to reproduce the results. In A I get similar numbers on when running scenario A a second time.

Also I guess that autocrcon or update can get in the way. Therefore we probably want to disable those also:

drush config-set system.cron threshold.autorun 0
drush pm-uninstall update
Fabianx’s picture

Anyone who tries to reproduce that, should use the same commit hash as in the spreadsheet.

Just saying in case it was not entirely clear.

znerol’s picture

Just saying in case it was not entirely clear.

This is entirely clear and nevertheless I entirely failed to reproduce the numbers, just like @dawehner before.

catch’s picture

Did you both have APCu enabled and in -use for the chained fast backend?

dawehner’s picture

I have apcu enabled, as I see apc_fetch() in all my profiling, so I guess chained fast backend will be used automatically then ...

catch’s picture

Yes it should be.

dawehner’s picture

@catch
Do you maybe hide PHP internal function calls?

Fabianx’s picture

Oh, yes that is a good point.

Lets compare xhprof configurations.

xhprof-kit uses:

xhprof_enable(XHPROF_FLAGS_MEMORY);

and nothing else as that was the best performance after many tests and feedback from others.

catch’s picture

Hmm so this could be it, I use the same prepemd/append files for 7.x/8.x at the moment,,,

xhprof_enable(XHPROF_FLAGS_CPU + XHPROF_FLAGS_MEMORY, array('ignored_functions' => array('call_user_func', 'call_user_func_array', 'module_invoke', 'module_invoke_debug', 'module_invoke_all','module_invoke_all_debug', 'theme', 'drupal_alter')));

Fabianx’s picture

#53: Oh, yes.

Also be aware that using ignored_functions while fantastic for actually finding problems, screws up statistics a lot as the overhead in my benchmarks was way higher when using that.

Which could also explain the performance difference in absolute numbers ...

I think ignored_functions should be added to the xhprof-UI, because it should be possible to re-write the graph based on a list of ignored functions dynamically at run-time or filtered once.

Will ping sdboyer for that as that is definitely graph related :).

catch’s picture

I'll try to redo without, that was silly.

cthos’s picture

I've been working on profiling against d579f513623cf3ccd7, and I'm getting similar numbers to #31 but they're not identical.

However, that's to be expected. The call graph will only be identical for the given configuration, and only if the code doesn't branch in ways that aren't readily apparent. However, I am getting consistent results when redoing the scenario. (For example, I'm not super well versed in how D8 is scanning for modules, but if it's similar to D7, the number of filesystem calls will grow linearly with the number of modules, since it's doing a recursive file scan to parse things).

https://docs.google.com/spreadsheets/d/1Guco0_SSIlygtOeWYfcE0CrUOqk6XHeu...

Here's my current setup:

System Info

Drupal VM (https://github.com/geerlingguy/drupal-vm)
php5.6 (5.6.11-1+deb.sury.org~trusty+1)
Zend Engine v2.6.0, Copyright (c) 1998-2015 Zend Technologies
    with Zend OPcache v7.0.6-dev, Copyright (c) 1999-2015, by Zend Technologies
    with Xdebug v2.2.5, Copyright (c) 2002-2014, by Derick Rethans
Apache/2.4.12

XDebug is disabled via php.ini, APCu enabled for all tests. Mysql is running on the same machine as apache, but since we're not going for timing, I don't think that matters too much.

Methodology

Running XHProf, the following has been added to the top of index.php:

register_shutdown_function(function () {
  $prof_results = xhprof_disable();
  file_put_contents(ini_get('xhprof.output_dir') . "/" . uniqid() . ".Drupal.xhprof", serialize($prof_results));
});
ini_set('opcache.enable', 0); // only for scenario A
xhprof_enable(XHPROF_FLAGS_MEMORY);

The opcache.enable = 0 call is made for scenerio A and removed entirely for the others.

Using the xhprof_html renderer for easy access to sorting and the full callgraph. Memory usage on my sheet is coming right out of XHProf which should be relatively similar to memory_get_peak_usage(), so I've omitted the patch to index.php for adding the call at the end.

Since register_shutdown_function is a FIFO queue (if I'm remembering correctly) this could be missing some calls happening on shutdown though.

Edit: There are only 2 shutdown functions (including that one), so I don't see that being statistically significant. But I also hacked it to the bottom of the queue, and the results were very similar.

effulgentsia’s picture

#56 is encouraging. I created yet another gdoc (https://docs.google.com/spreadsheets/d/1_XbRrwEcqiLyDrWh3zTmOoVUaCzJ_oLM...) showing the differences between #31 and #56.

I think minor differences between people/computers is fine, per explanation in #56. Especially since what matters most is being able to make conclusions about 2 different commit hashes (i.e., has HEAD regressed unacceptably from one point in time to another), so if different machines can at least generate numbers that lead to the same conclusion, that might be sufficient.

So, I colored red the cells that lead to a different conclusion. Figuring out the source of those differences between catch and cthos would be worthwhile. I also colored red the cells that show a memory usage above 64MB, since that's what D8 currently claims to run within, so if in fact it needs more, we need to correct that claim.

cthos’s picture

So, I colored red the cells that lead to a different conclusion. Figuring out the source of those differences between catch and cthos would be worthwhile. I also colored red the cells that show a memory usage above 64MB, since that's what D8 currently claims to run within, so if in fact it needs more, we need to correct that claim.

XHProf UI can do a diff comparison between two xhprof runs. It might be worthwhile to each generate a callgraph and then run it through the diff tool.

Also, I think I still had opcache turned off on the newer commit hash for a few requests, which would cause some memory jumps. Let me verify that.

Edit: Also I'm going to write up some casperjs scripts to automate the scenarios. I'll share them here when I'm finished.

Fabianx’s picture

+1 to #58 (automating somehow)

Note that I run a "shared xhprof hosting service" - well, enough buzzwords, a little script that allows trusted community members to upload xhprof runs to the web and make them available via the github.com/LionsAd/xhprof-kit script.

While the upload.php was made specifically with xhprof-kit in mind, there is nothing stopping anyone from re-using the same for uploading arbitrary custom benchmarks.

Ping me via mail or IRC if you need an API key.

cthos’s picture

Here's my WIP casper scripts: https://github.com/cthos/d8-perf-casper. Mostly working, I just need to toss in some of the drush steps before it.

I'll probably also change the xhprof methodology to use prepend / append files so I can get it to spit out a link to automatically open the relevant xhprof run.

Edit: Bash helper wrapper thing around it now, along with instructions on what's going into index.php. Working on moving that to a prepend file / etc.

cthos’s picture

@effulgentsia - I've corrected my memory readings for everything but A, I did have a few where opcache was off.

effulgentsia’s picture

Thanks. I updated the sheet in #57 based on your current numbers in the sheet in #56. Why do you think scenario D2 still shows such a high memory jump for you between the two commit hashes?

cthos’s picture

Probably a weird fluke with the setup. I'm currently trying to pin down why the casper scripts are generating more xhprof files than I'd expect them to be generating. I plan on tweaking a bit so I can target very specific things instead of shotgun profiling every request.

Fabianx’s picture

#63: Use index-perf.php from xhprof-kit, just need to tweak the casper visited urls to use:

/index-perf.php?url=real-encoded-url-with-parameters

catch’s picture

@cthos there may well be some ajax requests in there for toolbar, comment history etc.

Fabianx’s picture

#65: Using a index-perf.php instead of an after appended script and having to hack index.php avoids that problem for me in xhprof-kit.

cthos’s picture

#66: Yeah, I cleaned this up here: https://github.com/cthos/d8-perf-casper/commit/d6dc16596ffaab7ae82b3e614... which along with a fix to casper not generating the test user in D.js has fixed the noise problem (wobbling on a $_GET param to trigger xhprof).

I've corrected the memory allocation in D2 on my spreadsheet.

Now that it's automated, it should be fairly consistent. @catch - how were you avoiding the possible function call changes when doing this manually? With all of the moving parts it is conceivable that state could change between requests causing a different number of calls (cache state change, db state change, etc).

@Fabianx - I'll do a full run of what I've got and upload the xhprof files for group review here in a little bit via xhprof-kit.

catch’s picture

@cthos the steps should be explicit enough that the code path is the same each time - at least I was able to reproduce the same numbers with two full runs on my machine. If they aren't, then I think we should consider modifying the steps so that this is the case - it's more important to get consistent results than those exact scenarios. We really suffer from not having a centralised infra for this, but that didn't happen.

One thing that's not in the steps is disabling automated cron (although that was discussed in irc or above), that won't help much if it's on and gets triggered.

cthos’s picture

So here are my full latest results against the 0dbb619f9d5ef8beae4f for examination:

A1 POST - 55b9251b3733f
A2 - 55b9251d8eb86
B1 - 55b926390e9b3
C1 - 55b947b193c50
D1 - 55b92b78d42b0
D2 - 55b92b796d205
D3 - 55b92b79e7ad8
D4 - 55b92b7a4dd10
D5 - 55b92b7b69e68
D6 - 55b92b7c7a361

Re: #68: The reason I bring this up is because a complex application isn't a state machine, and there can be a lot going on under the hood which can modify the call graph (seemingly mysteriously over time). The scenarios are attempting to control for cache, but there are other states that can change these numbers (like the cron running, APCu getting cleared, or filling up, or other cache suddenly changing, or the filesystem adding scan calls because who knows what, etc.).

I just want to be wary of saying that the function call numbers will ever be 100% consistent between the same tag (or any of the other metrics really). I too can produce a consistent number now that I've automated all the tests, but something as simple as visiting another page (or having an ajax call not fire) can make subtle changes to the application layer that affects the callgraph.

My sense is this could be very useful as a smoketest, but you'd never want to say have a testbot failure if the function call numbers are simply higher between two tags, for example.

dawehner’s picture

yeah I think this would be much rather a metric which gives us some warning that something worse happened, so we might better have a look into it in more detail
at some point in the future.

Fabianx’s picture

#69: That is correct, however we do know the code paths pretty well and indeed random things except cron would be ... a bug.

Can we disable cron via casperjs without affecting caches somehow?

Maybe insteead of relying on installation, rely on 'drush cr'?

For xhprof-kit cold cache profiling that worked well for me. (obviously then only aggregated across 10 runs instead of 100 or so ...)

---

#69: C1 should be page cache, that cannot be right as it shows 22k function calls, so is not a warm cache.

cthos’s picture

Fixed C1. Though something is weird since Casper's not reporting that one appropriately. I'll confirm.
Edit: Definitely something up with C.js, mostly in the form of extra APC loads.

Don't forget there can be misconfigurations at the system level as well. All I'm saying is in order to get consistent numbers there are a lot of variables to control for and the level of effort on it I'd expect to be high.

cthos’s picture

With @Fabianx's help, https://github.com/cthos/d8-perf-casper has been modified to make use of xhprof-kit's index-perf.php file, which has smoothed out a lot of the overprofiling and cache invalidation issues (C1 in particular I wasn't getting good results on because it had a different cache key).

effulgentsia’s picture

So what I suggest as a next step here is for several (2-4 or so) people to independently try to use the scripts provided in #73 to determine the number of function calls, number of db queries, and peak memory usage for the various scenarios (see issue summary and/or #69) for beta-12 and beta-13. And based on that, answer the question of: is there a regression for a scenario/metric between beta-12 and beta-13 that we should investigate? I think once we have confidence that the scripts provide an acceptable smoke test for answering that question, then we can probably close this issue, and have confidence that we'll be able to repeat the process in order to answer that question for whether there's a regression between beta-13 and HEAD prior to tagging RC-1, as per checklist item #9 in #2485119: [meta] The Drupal 8.0.0-rc1 Release Checklist.

dawehner’s picture

Just tried out the script and well, I get the following debug output:

 ./run_scenario.sh A @d8.dev
Running site-install on @d8.dev
Starting Drupal installation. This takes a while. Consider using the --notify global option.                                                                                                                                                                         [ok]
Installation complete.  User name: admin  User password: grrcC4qLWM                                                                                                                                                                                                  [ok]
Congratulations, you installed Drupal!                                                                                                                                                                                                                               [status]
The password for admin is
2015-07-31 21:07:03.327 phantomjs[34549:1558016] *** WARNING: Method userSpaceScaleFactor in class NSView is deprecated on 10.7 and later. It should not be used in new applications. Use convertRectToBacking: instead.
[info] [phantom] Starting...
[info] [phantom] Running suite: 5 steps
[debug] [phantom] opening url: http://d8.dev/index-perf.php?url=/&disable_opcache=1&disable_xhprof=1, HTTP GET
[debug] [phantom] Navigation requested: url=http://d8.dev/index-perf.php?url=/&disable_opcache=1&disable_xhprof=1, type=Other, lock=true, isMainFrame=true
[debug] [phantom] url changed to "http://d8.dev/index-perf.php?url=/&disable_opcache=1&disable_xhprof=1"
[debug] [phantom] Successfully injected Casper client-side utilities
[info] [phantom] Step 2/5 http://d8.dev/index-perf.php?url=/&disable_opcache=1&disable_xhprof=1 (HTTP 200)
[info] [remote] attempting to fetch form element from selector: 'form[id="user-login-form"]'
[debug] [remote] Set "name" field value to admin
[info] [remote] submitting form to /node?destination=/node, HTTP POST
[info] [phantom] Step 2/5: done in 1759ms.
[debug] [phantom] Navigation requested: url=http://d8.dev/node?destination=/node, type=FormSubmitted, lock=true, isMainFrame=true
[debug] [phantom] url changed to "http://d8.dev/node?destination=/node"
[debug] [phantom] Successfully injected Casper client-side utilities
[debug] [phantom] opening url: http://d8.dev/index-perf.php?url=/admin/modules&disable_opcache=1&disable_xhprof=1, HTTP GET
[debug] [phantom] Navigation requested: url=http://d8.dev/index-perf.php?url=/admin/modules&disable_opcache=1&disable_xhprof=1, type=Other, lock=true, isMainFrame=true
[debug] [phantom] url changed to "http://d8.dev/index-perf.php?url=/admin/modules&disable_opcache=1&disable_xhprof=1"
[debug] [phantom] Successfully injected Casper client-side utilities
[info] [phantom] Step 4/5 http://d8.dev/index-perf.php?url=/admin/modules&disable_opcache=1&disable_xhprof=1 (HTTP 403)
[info] [remote] attempting to fetch form element from selector: 'form[id="system-modules"]'
CasperError: Errors encountered while filling form: form not found
  ...src/d8-perf-casper:706 in fill
  .../src/d8-perf-casper/A.js:17
  .../src/d8-perf-casper:1335 in runStep
  .../src/d8-perf-casper:332 in checkStep
webchick’s picture

Issue summary: View changes
Issue tags: +Actionable D8 critical

Tagging this one as an actionable D8 critical, and updating issue summary with the stuff in #74 on a best-effort basis. Definitely could use review.

Fabianx’s picture

#75: Be sure to update xhprof-kit before attempting that. I have added some changes especially to support the casper scripts.

cthos’s picture

#75: It looks like this line: https://github.com/cthos/d8-perf-casper/blob/master/run_scenario.sh#L17 isn't functioning correctly when it's running the site-install. I'm not sure why it wouldn't properly be capturing stdout unless it was being sent somewhere else. (It tries to use grep and cut to figure out what the admin password is on the freshly installed site so it can emulate admin actions, if that part fails, the remainder of the script would do odd things).

moshe weitzman’s picture

Just set the password to a fixed value with --account-pass. That would avoid the need for this line entirely.

It doesn't matter here, but FYI this could the the Drush bug you hit - https://github.com/drush-ops/drush/issues/1270

cthos’s picture

Good point Moshe. I've updated the shell script to hard code the password in 13e8290, as per #79.

Fabianx’s picture

Assigned: Unassigned » Fabianx
Issue tags: +D8 Accelerate

Testing the script scenarios some more

dawehner’s picture

I could run Step A-C now perfectly, Step D/D2 is still flaky as in producing no output

cthos’s picture

#82: D has the debug flags turned off so you won't get verbose output. Does it display the links to XHProf? (if not, are you seeing the runs appear in the standard xhprof gui?

dawehner’s picture

@cthos
No I just see 3 xhprof files.

cthos’s picture

#84: Had a hard-coded site alias reference in the D case of the shell script.

https://github.com/cthos/d8-perf-casper/commit/f1397c894dcff70ad07957fff... addresses that.

dawehner’s picture

cthos’s picture

Nice catch, that's been merged.

moshe weitzman’s picture

So here are my full latest results against 0dbb619f9d5ef8beae4f, the same hash as in #69. I also populated the Google sheet:

A1 - 55ca0464a0922
A2 - 55ca0467f3ba1
B1 - 55c512030da14
C1 - 55c51488ba743
D1 - 55ca0153deabc
D2 - 55ca0154a9a2e
D3 - 55ca01558bf42
D4 - 55ca015686be5
D5 - 55ca015847524
D6 - 55ca01599b8ed

cthos’s picture

#88 - Yeah, that's definitely weird. Casper's had support for child_process for years (https://github.com/n1k0/casperjs/issues/484).

Sounds like there's an issue with the underlying phantomjs implementation, but that's also been around for a long time.

Re: A2, I'll put some time into capturing the response and stopping the automatic redirect so that we can manually trip the page load through index-perf.php.

Also, as an enhancement to A1, we might be able to have xhprof-kit send a header back with the link to the run, so it can be captured on POST requests with a redirect. I'm assuming output isn't sent by then because of the location header, but I'll experiment a bit.

Edit: Looks like Symfony's http router does some ob_get* magic when it builds the response, so the header idea might be a bit tricky to do from a wrapper.

moshe weitzman’s picture

I copied all the metrics from cthos runs in #69 to the Google Sheet. There are now 3 sets of metrics for the same Git hash (catch, cthos, moshe).

cthos’s picture

https://github.com/cthos/d8-perf-casper/commit/2bf1b87107fdc8b921f91ce39... adds the ability to stop a redirect in order to make A2 profileable (the readme's updated in the subsequent commit).

justAChris’s picture

Regarding #88, I had the same child_process error when I used casperjs installed from homebrew. Switched to "Installing from git" instructions and now am able to run through all of the D scenarios without error. Something is up with the homebrew package.

moshe weitzman’s picture

I updated my Casper scripts and re-installed via NPM and now I am completing all scenarios. I updated #88 and the Google sheet. This exercise is still quite tedious, even having overcome environment issues.

cthos’s picture

#93 - So it might be possible to figure out what the memory and function call numbers are by piping the urls over to another script (or by using casper to load said page). The main issue there is XHProf doesn't provide any identifying information in the DOM to figure out what is what.

The DOM is probably the same every time though, so we can probably figure it out based on position.

Fabianx’s picture

I am still working on this, FYI.

I have scripts to get that information out of xhprof, but just in prototype form.

Also have a XHProf-Kit patch in the making to directly collect the run(s) into a pre-defined filename, just working out some local security concerns there - as so far installing xhprof-kit on production was kinda "safe".

Will submit a PR to d8-perf-casperjs and xhprof-kit soon.

I plan to fully automate that to the point where this can run on travis automatically and that is very very close already given I have drupal_ti for the travis part.

cthos’s picture

Just added a bit to scrape the XHProf results via casper: https://github.com/cthos/d8-perf-casper/commit/945a2eed0a6c3d7e4a865a226...

Hopefully that'll help you, @Fabianx

Edit: Just added the ability for it to go grab the PDOStatement::execute count as well, so it should print out all the metrics on the command line now.

dawehner’s picture

@sorressean
Those URLs seems all broken, as they don't have the right run IDs.

dawehner’s picture

@sorressean
What has been the version of Drupal you executed this against? Things like http://www.lionsad.de/xhprof-kit/xhprof/xhprof_html/?run=55d345b9ad871&s... should look a little bit better in HEAD.

sorressean’s picture

They should work a lot better in head. I actually used an older hash: the same one that Moshe and others have used: 0dbb619f9d5ef8beae4f. This is an older hash, so the performance would not be the same. I'm trying to collect results on a hash that others are using.

dawehner’s picture

Oh yeah I was just curious ... one day we could then compare and hopefully improved over time.

sorressean’s picture

I totaly understand. I think it would be nice to have profiling happening closer to head to detect any issues, but this was hard enough to get working (and still has problems) that it isn't really viable. For now, I think it makes more sense to profile on hashes other people are profiling on to try to get something close to the same results. We can obviously see how that worked out.

chx’s picture

I absolutely disagree with this being critical. This should've been critical four year years ago and now it's simply too late.

moshe weitzman’s picture

Status: Needs review » Reviewed & tested by the community

I think this Task is complete. We initially scoped this issue for identifying profiling scenarios. Thats been complete for months now. The scope then expanded to "and get x number of people to run these scenarios on y number of hashes and results should match with z deviation". Despite this significant scope expansion, Acquia and others invested hundreds of hours into this issue. We now have Casper scripts for folks to run, and have posted results for 4 different people for the hash 0dbb619f9d5ef8beae4f. See the Google Sheet.

D8 performance has been improving at a good pace for many months now. Lets close this issue and keep improving elsewhere. The scenarios and scripts developed here will be useful when we complete the Release Checklist (coming soon!).

catch’s picture

Status: Reviewed & tested by the community » Fixed

Yes the C, D and E columns in the spreadsheet are pretty close which is all I wanted to get this issue done. Moving to fixed.

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.