Add OpenTelemetry Application Performance Monitoring to core performance tests

Couple more lines to bring in from the other issue.

Re-rolled based on the latest changes in #3346765: Add PerformanceTestBase for allowing browser performance assertions within FunctionalJavaScriptTests.

Extra cleanup.

Still need to fix #7, couple more changes now this is based on the base class from the parent issue.

Had a quick look at getting environment variables in Symfony and they have a whole separate API for it, couldn't see a simple wrapper like the request object unless I'm missing something obvious.

New patch which abandons first content paint and largest contentful paint for now since they don't seem to be reliably available in the chromedriver log, and just does time to first byte instead.

Need to set span.kind to server for it to show up in the Jaeger monitoring tab.

Adding an extra request and renaming the anonymous test so we can log/graph node/1 too.

Using the performance timing API now - seems more reliable.

I've updated the issue summary to show a screenshot of how this looks in Jaeger/Prometheus and a bit more information about the implementation.

#3346765: Add PerformanceTestBase for allowing browser performance assertions within FunctionalJavaScriptTests landed so this now just needs #3352389: Add open-telemetry/sdk and open-telemetry/exporter-otlp as dev dependencies.

Re-rolled now that #3346765: Add PerformanceTestBase for allowing browser performance assertions within FunctionalJavaScriptTests is in.

Could definitely use high-level review!

The best way to try this out is to use the repo at https://github.com/tag1consulting/google-drupal, should be just a couple of steps if you already have ddev, or a handful of steps if you don't. That way you get a local instance and can see what it looks like - very sparse at the moment but shows where things could go.

As it currently stands there is no public opentelemetry instance for us to log to, but I think the dependency issue landing and this one getting some review would be enough to make it worthwhile setting one up (although possibly not jaeger/prometheus - have been discussing using https://signoz.io/ with @nnewton but that is still @todo and TBD). Until we have a telemetry instance and gitlab CI setting the environment variables, this will be dead code in core and only useful for local development. So there is a bit of chicken and egg there.

Switching to an MR now the two dependencies have landed.

The testing repo needs updating for the latest core commits again so best to hold off trying to test that for now. [edit, this needs #3352389-34: Add open-telemetry/sdk and open-telemetry/exporter-otlp as dev dependencies to land]. [edit again: now fixed in the testing repo] Patch should be the same so leaving at needs review.

I sort of found a way to get Largest Contentful Paint originally, but also it was unreliable due to the way chrome logging works, so that is still TBD. The code for that (as far as I got) is in #3352459-8: Add OpenTelemetry Application Performance Monitoring to core performance tests.

The problem is that the chrome performance log can only get you Largest Contentful Paint candidates and it's up to interpretation which one is the actual Largest Contentful Paint (it should be the last one for any particular request generally).

What I was finding was that the first request in a test would not produce anything for LCP (i.e. there would be no candidates at all), but then the second or third request would, which suggests some kind of warm up or race condition issue with the chrome performance log or some artifact of retrieving the log programmatically in phpunit vs. looking at it in dev tools.

This is also an issue with the performance typing API which I switched to in #3352459-12: Add OpenTelemetry Application Performance Monitoring to core performance tests - i.e. it's better for everything else but still unreliable for LCP.

Have done a bit more work on the dashboard, switching from Jaeger + Prometheus standalone, to Prometheus + Grafana + Grafana Tempo. Grafana gives us a lot more options to display data, and Grafana Tempo handles traces. This is still early days but you can see the possibilities.

I've also updated the MR to handle largest contentful paint again, after figuring out the weird things going on in the chrome performance logs (see inline comments). The dashboard is now able to expose the LCP issue in Umami from #3349447: Improve Largest Contentful Paint in Umami front page on the front page - compare the timings for to node/1.

I've posted a chromium bug report here: https://bugs.chromium.org/p/chromium/issues/detail?id=1463436

There's two further ways to get the LCP event:

1. embed JavaScript on the tested site and log to opentelemetry from the tested site instead of the test. i.e. we'd need an opentelemetry module which we install during tests. This is how you'd do it for a production site because of course you don't control the browser in that case.

I started doing this with chromedriver instead because 1. I didn't think it would be this hard ;) 2. there's some data from the performance log we can assert on, so it's useful not only for opentelemetry 3. it leaves the tested site 'clean' without additional JavaScript - for example we have tests that ensure there is no anonymous js at all in the standard profile, once we add js we can't test the non-js state.

2. Inject some js via chromedriver, with an event listener for performance events into the browser instance, have that listen to the various events, using its own timer (so ignoring the timestamps of the events), then collecting that log in the test. but... no idea if that's possible with the behat/mink APIs.

We'll need to run some PHP on the tested site to collect things like database queries etc. but that is completely unavoidable (and it'll be easier to account for than having js vs. none at all). But.. we could switch to a more 'production' APM set-up with the trade-offs acknowledged if we need to.

Another dashboard update, but getting much closer to something actually useful now.

The dashboard/tests are now at the point where you can visually see the improvement from #3349447: Improve Largest Contentful Paint in Umami front page in the graphs on the OpenTelemetry side (which is the repo in the issue summary).

The green dots are LCP, the blue dots are FCP, the yellow dots are TTFB.

After the patch is applied, the green dots and blue dots merge - this means instead of two Largest Contentful Paint events, there is only one, which happens to be the same paint as the First Contentful Paint. Can also see the timings go down by 150-200ms.

I'll try to reproduce this one more time and post some better screenshots including traces next week.

I was looking through what we log to otel today and wondered if there was any way to get the ttfb, lcp and fcp numbers returned from PerformanceTestBase after calling drupalGet(). In addition to logging to otel, we could also write asserts that one of these stats is less then X seconds?

It's definitely possible, the problem is once we have random failures no-one trusts anything, which is already a problem with normal js testing.

I had to split #3361833: Add image request counts to PerformanceTestBase out of the PerformanceTestBase issue since you sometimes get 7 or 8 images loaded between requests, which I assume is something slightly non-deterministic about how chrome calculates whether an image needs to be lazy loaded or not. Haven't gone back to that one recently.

Having said that, with Umami the FCP and LCP are exactly the same event after #3349447: Improve Largest Contentful Paint in Umami front page, and this is probably already the case for the standard profile. So... I wonder if we could use assertIdentical()? That would only catch a certain class of issues but it'd be more than nothing. We'd probably need to do the 'run the test 10,000 times' thing to make they really are identical and there's aren't occasional requests where chrome does something different.

On actually running these tests, my proposal is we run them sort-of twice:

1. On normal phpunit test runs, we don't set OTEL_COLLECTOR, so that collection doesn't happen. However running the test will make sure they don't get broken by other changes in core.

2. In a separate gitlab pipeline, we'd run the tests on a schedule against each branch (hourly + after each commit might be good), with no concurrency, so that the machine is doing one thing at a time. Hopefully that way we'll get more consistent results. However while this will hopefully help to avoid huge variation in the otel data, it won't help with consistency in timings for general test runs.

General note I looked into combining the test methods into a single method and clearing caches in the appropriate places etc. to try to reduce the number of times we need to re-install core, but that led to inconsistent results all over the place. So if we want to try to do that, it would be better done in a follow-up issue when we've got a consistent set of results to compare against. The chrome performance log is unfortunately not easy to work with like this.

I'll try to go through the MR nits soon. Also want to add a similar test case to the umami one for the standard profile. And maybe some logged in tests for both.

We need the grafana stack + gitlab pipeline set up before this can actually do anything publicly accessible (although that's part of the google project this is funded by), so while it would be great to have it committed, there are more steps to getting it going.

I've opened some follow-up issues postponed on this one for adding more information to traces. It would be possible to do here, but trying to keep this reviewable.

#3377660: Add authenticated user telemetry tests
#3377657: Add database query spans to otel traces
#3377654: Support 'interaction to next paint' (or close equivalent) in performance testing
#3377655: Add script, style, image HTTP requests to otel traces

I've added the following three follow-up issues as requested by Wim. Think I was able to resolve all the other threads too.

#3379761: Add the commit hash to OpenTelemetry traces
#3379757: Track largestContentfulPaint::candidate events in PerformanceTestBase and allow assertions on them
#3379750: Figure out cold start issue with chromedriver performance logs

No good reason! Deleted!

Sorry bot but I don't believe you.

Not sure what happened to it, but did a rebase which seems to have cleaned up the MR.

But question, with all the work of gitlab where would this fall into that workflow?

So the idea is that we'd configure a specific pipeline job that sets the environment variable with an open telemetry endpoint, and then run only --group OpenTelemetry tests (directly with phpunit, not run-tests.sh). This would run only on scheduled core pipelines, not MRs or commits. That way the data going into the graphs is from core branches and on a predictable schedule.

Would/could it be a tab reviewers could see like the "test-only" tab being worked on?

No because this only populates the grafana/tempo installation per the above screenshots, and it's specific for things that can vary slightly between tests like timings that we can't easily add assertions for. However, once we have a public grafana/tempo instance for gitlab ci to point to, we'd be able to have a public dashboard either at a URL like core-performance.drupal.org and/or embedded somewhere. Exactly where to put it is tbd. Here's Gutenburg's (very different) dashboard for comparison: https://www.codevitals.run/project/gutenberg

Addressed @quietone's points on the MR (I think) - leaving RTBC since these were 100% comment changes.

Removing the FEFM and release manager review tags, we'll need RM review if we add alerting or similar in (which would be on the grafana end), but just for having this in core and producing the dashboard I think the main thing is the implementation here.

Looking at this and \Drupal\FunctionalJavascriptTests\PerformanceTestBase::drupalGet() makes me think that we should aim to remove most of the logging code from PerformanceTestBase and put it in a middleware like Drupal\Core\Test\HttpClientMiddleware\TestHttpClientMiddleware

I'm not sure about the best way to register the middleware but maybe putting it in \Drupal\Core\CoreServiceProvider::registerTest() for now would be okay.

I started to look at a middleware, but realised we'd need a static + getter and setter to set telemetry logging on and off, then another static + getter and setter to hold stylesheet/script counts so that the test can assert on them.

However, I then realised a trait should be possible without the above drawbacks, so I've pushed a new branch that starts work on this.

Originally rejected a trait here here because PerformanceTestBase needs to override setUp() etc. in a way that normal class inheritance can continue to function, but we can do that by still having PerformanceTestBase and it calling out to some helpers. Then a different test base would have to do the same thing but that's only a little bit of boilerplate not hundreds of lines of code.

@alexpott mentioned in slack that a middleware would make logging telemetry data from non-drupalGet code easier - I think we can achieve this with the trait via a similar trick to logTelemetryData() so have added ::collectPerformanceData($callable, ?PerformanceData $performance_data);

This will either allow for logging performance data from things like form submissions, link clicking or drupalPost() out of the box, or with very little modification in a follow-up. It also means that other requests (log ins, cache warming), don't bother looping over the chrome performance log to collect request counts etc.

However it's a large refactoring of the existing PerformanceTestBase class that's already in HEAD, and I don't want to get bogged down here, so unless the API change here helps to get this issue committed faster, we might want to move that to a follow-up? There's still time to change the API before 10.2.x alpha/beta is tagged but not that much, and I don't want to be then adding bc layers in this issue too.

If the new approach looks OK we should update https://www.drupal.org/node/3366904, none of this is in a tagged release yet so just updating the existing change record should be fine.

I am not 100% on the PerformanceData value object, it gets rid of the class properties and makes everything more explicit but it also makes the profile requests more verbose. Generally the performance requests being more verbose feels like it's probably fine, it's good to make that explicit rather than implicit to differentiate them from setup/warmup steps.

Originally I thought that the collectPerformanceData() could just return the $performance_data object, but as it also needs to return the result of the inner closure, passing it as an argument is the best solution indeed.

Yeah I didn't have a better idea. I don't know when we ever actually use the return value of drupalGet(), especially in web driver tests, but if don't return the callable return, there's no way to do it.

I guess we could maybe do something like PerformanceData::getOriginalReturnValue() or something, and stick it in there, then we can get rid of the argument and have less boilerplate. That would be an easy change to make but will wait for feedback before doing it.

Updated the MR for the change in #72.

I've updated the 'API changes' section here, this can become the basis for the updated CR after commit too.

Updated https://drupal.org/node/3366904.

Looks like the commit didn't go through.

Managed to get a wrong array key in some of the refactoring. This code only runs when tracing is enabled which is not the case yet.

That seems like it would be intermittent, the tests themselves don't do anything special.

I've opened #3392125: Random test failure in Drupal\Tests\demo_umami\FunctionalJavascript\PerformanceTest, if it's #93 there might be a quick fix.

Also I'm a bit surprised that it's hitting this test in particular, because it predates this issue, rather than the new tests that were added here, but maybe it's one of the logic changes somewhere.

Have a non-optimal but working patch on #3392125: Random test failure in Drupal\Tests\demo_umami\FunctionalJavascript\PerformanceTest so going to go ahead and move this back to fixed.

Update just to say there is now a working public dashboard at http://grafana.tag1demo.tag1.io/d/teMVIdjVz/umami?orgId=1&refresh=30s&fr... it is currently populated by pushing buttons on the MR from #3391689: Add a performance tests job to gitlab and send data to OpenTelemetry which could use review.

@tyler36 open telemetry has a new release out so you may be running into an issue with that.

I've committed #3395453: Bump "open-telemetry/*" to latest to make daily "updated deps" QA run pass again so a composer update on the sandbox repo might fix the issue for you now.

Note that the repo also currently doesn't account for fixes in #3391689: Add a performance tests job to gitlab and send data to OpenTelemetry but those shouldn't (hopefully) block getting something up and running.