Track cache tag queries separately in performance tests

Created on 16 February 2024, 9 months ago
Updated 7 March 2024, 9 months ago

Problem/Motivation

Cache tag queries, although we want to know about them, are different from other database queries in that they won't run on every (or even most) sites due to redis/memcache. Like 📌 Separate cache operations from database queries in OpenTelemetry and assertions Fixed we can split them out and track them separately. Will help 📌 Log every individual query in performance tests Needs work too.

Steps to reproduce

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

Release notes snippet

📌 Task
Status

Fixed

Version

10.3

Component
PHPUnit 

Last updated 1 day ago

Created by

🇬🇧United Kingdom catch

Live updates comments and jobs are added and updated live.
Sign in to follow issues

Merge Requests

Comments & Activities

  • Issue created by @catch
  • Pipeline finished with Failed
    9 months ago
    Total: 200s
    #96679
  • Pipeline finished with Failed
    9 months ago
    Total: 174s
    #96682
  • Pipeline finished with Failed
    9 months ago
    Total: 480s
    #96684
  • Pipeline finished with Failed
    9 months ago
    Total: 579s
    #96693
  • 🇧🇪Belgium wim leers Ghent 🇧🇪🇪🇺
  • Pipeline finished with Failed
    9 months ago
    Total: 172s
    #96908
  • Pipeline finished with Failed
    9 months ago
    Total: 594s
    #96912
  • Pipeline finished with Failed
    9 months ago
    Total: 484s
    #96945
  • Pipeline finished with Failed
    9 months ago
    Total: 484s
    #96954
  • Pipeline finished with Failed
    9 months ago
    Total: 480s
    #96961
  • Pipeline finished with Failed
    9 months ago
    Total: 606s
    #96969
  • 🇬🇧United Kingdom catch

    The MR is up, I'm seeing variations though in both the isValid and checksum counts, in what might be both directions, when running on gitlab - this potentially explains the query variation we're seeing elsewhere and might mean we can use exact assertions for database queries once this lands. Need to get to a green MR though..

  • Status changed to Needs review 9 months ago
  • 🇬🇧United Kingdom catch

    Should be ready for review now.

  • Status changed to RTBC 9 months ago
  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    Looks good to me. Tests also went green on my local and the changes will help me in reducing the expected results of 📌 Log every individual query in performance tests Needs work

  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    Still RTBC for all I care as you can fix on commit, but minor copy-paste mistake in a comment.

  • Status changed to Needs work 9 months ago
  • 🇧🇪Belgium wim leers Ghent 🇧🇪🇪🇺

    A few questions + nits 😇 But … I'm definitely intrigued! 🤩

  • Pipeline finished with Canceled
    9 months ago
    Total: 322s
    #99224
  • Pipeline finished with Success
    9 months ago
    Total: 512s
    #99229
  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    I applied the nits, the only two things still left for discussion are:

    • Do we keep using microtime()? -> Broader than this issue, should perhaps discuss in a follow-up
    • Should we switch to enum? -> Fine by me, but how do we use match() then?
  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    During one of many tests locally, StandardPerformanceTest::testAnonymous() failed on the checksum count:
    150 is greater or equal to 143 and is smaller or equal to 146

    This happened on only one out of 10ish test runs

  • 🇧🇪Belgium wim leers Ghent 🇧🇪🇪🇺

    Broader than this issue, should perhaps discuss in a follow-up

    +1 for follow-up to maintain consistency. Tagged for that.

    Should we switch to enum? -> Fine by me, but how do we use match() then?

    Posted suggestion (https://git.drupalcode.org/project/drupal/-/merge_requests/6643/diffs#no...), proof that it works: https://3v4l.org/VsQ3n

  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    While a match() definitely looks nicer and is more concise, I'm worried about the fact that we're not using it the way it was intended. We're executing an increment in a place where you're supposed to return a value and I'm not sure if php will keep allowing that for all eternity.

    Would you agree with a switch() instead?

            switch($operation) {
              case CacheTagMetrics::getCurrentChecksum:
                $cache_tag_checksum_count++;
                break;
    
              case CacheTagMetrics::isValid:
                $cache_tag_is_valid_count++;
                break;
    
              case CacheTagMetrics::invalidateTags:
                $cache_tag_invalidation_count++;
                break;
    
              default:
                throw new \LogicException('Uncaught cache tag operation found.');
            };
    

    The exception also takes care of your concern that we'd forget to count a newly monitored operation. I mean, it's definitely more verbose than the match() statement, but semantically it seems more correct?

  • 🇬🇧United Kingdom catch

    I opened the follow-up for hrtime in 📌 Use hrtime() instead of microtime() for timing things Active so removing the tag.

    We're executing an increment in a place where you're supposed to return a value and I'm not sure if php will keep allowing that for all eternity.

    It seems like the worst they could enforce is explicitly returning NULL?

    I personally find the match statement more readable than the switch statement (no break or default to worry about, which can always theoretically go wrong if one gets misplaced).

  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    Yeah, let's go with match(). I do agree it's far more readable.

    I withdrew my objection in the edit above. I just feel like this is a regression to oldschool php where things have magic meanings. How would you teach the difference now between switch() and match() if the latter can be duckpunched into behaving like the former :)

  • 🇧🇪Belgium wim leers Ghent 🇧🇪🇪🇺

    #12: let match() grow on you 😊 It had to grow on me too. The #1 benefit of match() is not brevity, but the language-level help to ensure all cases are covered — see UnhandledMatchError.

    #14: read https://stitcher.io/blog/php-8-match-or-switch — I'd argue the opposite is true: it's switch() that contains more magic than match() 😅

    Keeping at for implementing match() since both @catch and @kristiaanvandeneynde are on board now 😊

  • Status changed to Needs review 9 months ago
  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    Switched to enum/match and also made sure that we use the name property to get a strign we can send to OpenTelemetry as I've read enums do not support __toString().

    Furthermore made sure we actually send the cache tag stuff to OT (in our case Grafana) too and found something interesting. We are getting a bunch of calls where no tags were provided. See attached screenshot below. Only the one at the bottom actually had any tags, many of the resulting spans had none.

  • Pipeline finished with Failed
    9 months ago
    Total: 181s
    #100590
  • Pipeline finished with Success
    9 months ago
    #100597
  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    Come to think of it, these empty checks would explain the high number of cache tag operations we're seeing. Implementing code knows it's safe to call these operations with empty arrays and therefore does not bother checking how many tags there are before sending the (empty) list to the respective methods.

    If we were to run an empty check before we call any operation, the number would go down drastically.

  • 🇧🇪Belgium kristiaanvandeneynde Antwerp, Belgium

    Regarding declare(strict_types = 1); vs declare(strict_types = 1); I found >100 and ~90 use cases of them respectively. So unless we want to standardize on those I'd just leave it as is. PhpStorm seemed to manually add the spaces on my end.

  • Pipeline finished with Success
    9 months ago
    Total: 635s
    #100664
  • Status changed to RTBC 9 months ago
  • 🇧🇪Belgium wim leers Ghent 🇧🇪🇪🇺

    🚀 This will be very helpful to improve Drupal's use of cache tags 😊 Thanks for making this happen!

  • 🇧🇪Belgium wim leers Ghent 🇧🇪🇪🇺

    Oh and I think we already need a follow-up for the first finding, by @kristiaanvandeneynde in #16: we can optimize \Drupal\Core\Cache\CacheTagsChecksumTrait::isValid() with a trivial early return:

    if (empty($tags)) {
      return TRUE;
    }
  • 🇬🇧United Kingdom alexpott 🇪🇺🌍

    Committed and pushed 07a3ac8477 to 11.x and d552da855a to 10.3.x. Thanks!

  • Status changed to Fixed 9 months ago
    • alexpott committed d552da85 on 10.3.x
      Issue #3421881 by catch, kristiaanvandeneynde, Wim Leers: Track cache...
    • alexpott committed d66403c9 on 11.x
      Issue #3421881 by catch, kristiaanvandeneynde, Wim Leers: Track cache...
  • Automatically closed - issue fixed for 2 weeks with no activity.

Production build 0.71.5 2024