Problem/Motivation

Depends on #3352851: Allow assertions on the number of database queries run during tests which adds assertions for database queries (and cache operations) to PerformanceTestTrait.

This issue adds open telemetry spans for the database queries too - this means you can go to the Grafana dashboard, click on a trace, and see every query that was recorded for the request.

Because we cumulatively record database queries, if there is a redirect, AJAX requests, asset or image style route requests while recording, it will include those database queries too, so you get a complete view of what was executed as a result of the thing you were testing.

A potential follow-up would be to add EXPLAIN output for each of the queries too, but we might want to do that after fully separating out cache and other database queries, since there's no point EXPLAIN-ing dozens of identical cache gets #3396196: Separate cache operations from database queries in OpenTelemetry and assertions.

Steps to reproduce

If you want to manually test this, and have an existing core install based on ddev that can run functional javascript tests, you can do the following:

$ ddev add tag1consulting/gander
$ ddev restart

Then run any test from the Umami OpenTelemetry tests, e.g.:

../vendor/bin/phpunit profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryNodePagePerformanceTest.php --filter=warm

You can then go to http://localhost:3000/d/teMVIdjVz/umami?orgId=1&refresh=30s and browse through the traces.

https://github.com/tag1consulting/ddev-gander

Once it's merged, the same thing will be available via core branch runs on http://grafana.tag1demo.tag1.io/d/teMVIdjVz/umami?orgId=1&refresh=30s

Proposed resolution

The database API has query start/end events, we can use those verbatim to create open telemetry spans within PerformanceTestTrait.

It will then be possible to go to to the grafana dashboard, click on a trace, and see all the queries executed, the query string, the caller etc.

Remaining tasks

User interface changes

Screenshot from Grafana tempo trace view showing multiple database queries, how long they took, and an expanded query showing the query string, caller, arguments

API changes

Data model changes

Release notes snippet

CommentFileSizeAuthor
#5 Screenshot from 2023-11-28 23-26-27.png275.01 KBcatch

Issue fork drupal-3377657

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

Comments

catch created an issue. See original summary.

catch’s picture

Status: Active » Postponed
catch’s picture

Title: [PP-1] Add database query spans to otel traces » Add database query spans to otel traces
Status: Postponed » Active

catch’s picture

Issue summary: View changes
Status: Active » Needs review
StatusFileSize
new275.01 KB
catch’s picture

Category: Feature request » Task
Priority: Normal » Major
Issue summary: View changes
catch’s picture

Issue summary: View changes

Added testing instructions to the issue summary.

mondrake’s picture

Interesting... maybe in the future we could build over #3384999: Introduce a Schema::executeDdlStatement method and the dynamic queries API to provide more metadata as to the type of statement being executed - Data Definition (DDL), Data Manipulation (DML), etc...

See https://github.com/doctrine/dbal/blob/3.7.x/src/Connection.php#L1163-L1182 for definitions

catch’s picture

If possible it would be great to at least get INSERT vs SELECT into the query events, both for assertions and for scannability here, but I'm not sure if we have access to that in the spot where those are populated.

mondrake’s picture

We could by implementing some self describing metadata in the Database\Query classes and their extensions, and passing those into the events. Not immediate, but surely possible.

smustgrave’s picture

Status: Needs review » Postponed

based on the IS this is postponed on #3352851: Allow assertions on the number of database queries run during tests which is up for review but may be out of my wheelhouse but will try and keep an eye on it.

catch’s picture

catch’s picture

Issue summary: View changes
smustgrave’s picture

Status: Needs review » Reviewed & tested by the community

Much easier to review. THanks for also updating issue summary.

heddn’s picture

You got to it before me. But +1 on RTBC.

fabianx’s picture

RTBC + 1

alexpott’s picture

Version: 11.x-dev » 10.2.x-dev
Status: Reviewed & tested by the community » Fixed

Committed and pushed 0907775505 to 11.x and 571aeb51d8 to 10.2.x. Thanks!

  • alexpott committed 571aeb51 on 10.2.x
    Issue #3377657 by catch, mondrake: Add database query spans to otel...

  • alexpott committed 09077755 on 11.x
    Issue #3377657 by catch, mondrake: Add database query spans to otel...

Status: Fixed » Closed (fixed)

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