Problem/Motivation

We're seeing random query counts causing test fails. Let's list every individual query so we can see which queries have gone missing or suddenly popped up.

Steps to reproduce

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

Release notes snippet

CommentFileSizeAuthor
#18 3421164-nr-bot.txt90 bytesneeds-review-queue-bot

Issue fork drupal-3421164

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

kristiaanvandeneynde created an issue. See original summary.

kristiaanvandeneynde’s picture

Status: Active » Needs work

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.

catch’s picture

Priority: Normal » Major

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.

kristiaanvandeneynde’s picture

Priority: Major » Normal

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.

kristiaanvandeneynde’s picture

Priority: Normal » Major

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 :)

catch’s picture

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.

catch’s picture

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

kristiaanvandeneynde’s picture

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

kristiaanvandeneynde’s picture

Assigned: Unassigned » kristiaanvandeneynde

Will merge in the changes from #3421881: Track cache tag queries separately in performance tests and tag this issue as PP-1 if the other hasn't been committed by then.

kristiaanvandeneynde’s picture

Title: Log every individual query in performance tests » [PP-1] Log every individual query in performance tests
Assigned: kristiaanvandeneynde » Unassigned

Merged in your work, will see what testbot thinks.

kristiaanvandeneynde’s picture

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

kristiaanvandeneynde’s picture

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"',

Grafana reported this as coming from Drupal\Core\Session\SessionHandler, so this may be related to #3033791: Do explicit session garbage collection on cron

kristiaanvandeneynde’s picture

Title: [PP-1] Log every individual query in performance tests » Log every individual query in performance tests
Status: Needs work » Needs review

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

smustgrave’s picture

Status: Needs review » Needs work

Appears to need a rebase.

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

catch’s picture

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

Yeah that's the plan. #3423329: Prevent session garbage collection during functional tests, 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.

kristiaanvandeneynde’s picture

Status: Needs work » Needs review

Made the two methods static

needs-review-queue-bot’s picture

Status: Needs review » Needs work
StatusFileSize
new90 bytes

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.

kristiaanvandeneynde’s picture

Status: Needs work » Needs review
smustgrave’s picture

Status: Needs review » Reviewed & tested by the community
Issue tags: +Needs Review Queue Initiative

Feedback appears to be addressed and merge conflicts resolved

Excited to see this land.

  • catch committed ab2ab261 on 10.3.x
    Issue #3421164 by kristiaanvandeneynde, catch: Log every individual...

  • catch committed 51b09b25 on 11.x
    Issue #3421164 by kristiaanvandeneynde, catch: Log every individual...
catch’s picture

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

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!

wim leers’s picture

🤩 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 👏

wim leers’s picture

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.

slashrsm’s picture

Issue tags: +gander
catch’s picture

wim leers’s picture

Status: Fixed » Closed (fixed)

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