Log every individual query in performance tests

So the MR is a proof of concept.

1. The goal is to allow us to track queries that are highly variable and we don't really care about with aliases: watchdog_insert, sessions_insert, sessions_select, etc. We still see what happened, but without the detail.
2. Then, we replace highly variable arguments such as timestamp, IP address, username, etc. with capitalized keywords, such as TIMESTAMP, CLIENT_IP, etc.

This allows us to build a list of expected queries and compare it to what was actually tracked. We may need to sort the queries before comparing, but so far on my local they have always been in the same order.

NW because this isn't finished yet.

Bumping to major - this should allow us to track down the variation in query counts, which if we can go back to assertSame() will make the test coverage much more reliable. Also being able to assert individual queries will be useful in its own right in case we swap one query for another or similar.

Seeing a lot of SELECT "tag", "invalidations" FROM "cachetags" WHERE "tag" IN . We could perhaps track those separately like we do with cache gets, sets, etc. by checking for the calling class being DatabaseCacheTagsChecksum.

Just like we already check for DatabaseBackend to only log queries that didn't come from the DB cache, we could add in DatabaseCacheTagsChecksum to not track those queries either, then decorate cache_tags.invalidator.checksum and add some tracking in there.

Oops, cross-posted.

Okay so the final fail I'm seeing is related to a block ID being random (e.g.: "config:block.block.jf547b5k"8). But that only happens in a cache tag invalidation and as I wrote above we can stop tracking those as queries and simply do a count on them without being too specific.

So StandardPerformanceTest looking really good now. Need to apply the same approach to the Umami performance tests. But I'm on vacation as of right now, so will have to wait until next week :)

Seeing a lot of SELECT "tag", "invalidations" FROM "cachetags" WHERE "tag" IN . We could perhaps track those separately like we do with cache gets, sets, etc. by checking for the calling class being DatabaseCacheTagsChecksum.

Agreed with this, I thought I had an issue open for it already, but can't find it now. I briefly looked at decorating the cache tags service, but because the checksum implementation isn't part of the actual cache tags API as such, but a shared implementation/trait, the decorator approach didn't seem great. Just separating out the queries seems fine and we can always try a decorator approach later on.

Opened 📌 Track cache tag queries separately in performance tests Active which should hopefully make things easier here once it's in.

In the process of setting up a new laptop but once I'm settled in I'll review the other issue and merge it into this one

Will merge in the changes from 📌 Investigate variable database query counts in performance tests Active and tag this issue as PP-1 if the other hasn't been committed by then.

Merged in your work, will see what testbot thinks.

Tests go green with exact query counts, will try and do the same for Umami tests tomorrow.

All performance tests go green with exact query counts on my local now. I also removed the query aliasing in favor of parameter aliasing.

However, on one occasion, StandardPerformanceTest::testLoginBlock() had one extra query as the second-to-last query:

This was expected
      'SELECT "session" FROM "sessions" WHERE "sid" = "SESSION_ID" LIMIT 0, 1',
      'SELECT "name", "value" FROM "key_value" WHERE "name" IN ( "system.cron_last" ) AND "collection" = "state"',

This actually happened
      'SELECT "session" FROM "sessions" WHERE "sid" = "SESSION_ID" LIMIT 0, 1',
      'DELETE FROM "sessions"  WHERE "timestamp" < "TIMESTAMP"',
      'SELECT "name", "value" FROM "key_value" WHERE "name" IN ( "system.cron_last" ) AND "collection" = "state"',

Other issue got committed, so dropping the PP tag and removing draft status from the MR.

Appears to need a rebase.

Will this be a replacement for the performance checks where it assets the count between 2 values.

Will this be a replacement for the performance checks where it assets the count between 2 values.

Yeah that's the plan. 🐛 Prevent session garbage collection during performance tests Active , which I just opened based on @Kristiaan's report, will cover the one known random test failure (found via this issue), but this issue will help flush any more out.

Made the two methods static

The Needs Review Queue Bot → tested this issue. It no longer applies to Drupal core. Therefore, this issue status is now "Needs work".

This does not mean that the patch necessarily needs to be re-rolled or the MR rebased. Read the Issue Summary, the issue tags and the latest discussion here to determine what needs to be done.

Consult the Drupal Contributor Guide → to find step-by-step guides for working with issues.

Feedback appears to be addressed and merge conflicts resolved

Excited to see this land.

I originally thought something like this would be too much to maintain, but now that we've split out the cache and cache tag operations we're left with only 'real' database queries now, and the argument replacement, while it requires hard-coding some assumptions in PerformanceTestTrait is easy to follow. This will help massively with any future random variation similar to the session gc one and gets us back to precise assertions again.

Committed/pushed to 11.x and cherry-picked to 10.3.x, thanks!

🤩 This is incredibly helpful! Agreed that it wasn't feasible before, but it now is, and that alone is a strong indicator of the progress that's been made 👏

Oh, and it shows already that in real sites, there would be one DB query less:

      'SELECT "name", "value" FROM "key_value" WHERE "name" IN ( "drupal.test_wait_terminate" ) AND "collection" = "state"',

(that's a test-only DB query, caused by \Drupal\Core\Test\StackMiddleware\TestWaitTerminateMiddleware.

#25 yes that's been annoying me, opened 📌 Move the test wait terminate service to a test module Active .

quietone → closed merge request !6582

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