Allow the database query log to be dispatched as log events

Created on 4 October 2022, over 1 year ago
Updated 19 March 2023, over 1 year ago

Problem/Motivation

When instrumenting a Drupal-based project, it's helpful to give performance tracing/profiling code real-time insight into operations and their sub-operations. For example, rendering one template might cause an another template to render, which causes a database query to retrieve some data from the cache. This hierarchy of parent and child operations (aka spans) can be visualized by the profiler.

The database subsystem has a built-in query log which allows database queries to be collected in a log and later retrieved by a profiler, but doesn't do anything to allow profilers to fire off a callback as queries execute. As a result, profilers can't easily build that nice hierarchical view of operations, whereas this is easily doable for other subsystems, such as Twig, which allows extensions to execute code as templates are rendered.

Proposed resolution

When database query logging is enabled will now an event being dispatched at the start of the query and at the end of the query. This will allow profilers to collect and log database query starts and ends. This can than be combined with other logged data to better analyse and debug Drupal.

Remaining tasks

Review, write tests, add change record.

User interface changes

None.

API changes

API additions:

  1. The method Drupal\Core\Database\Log::logFromEvent() adds database query loggings events data to the query log.
  2. The method Drupal\Core\Database\Connection::isEventEnabled() returns the status of the database API events being dispatched.
  3. The methods Drupal\Core\Database\Connection::enableEvents() and Drupal\Core\Database\Connection::disableEvents() enable or disable the dispatching of database API events.
  4. The method Drupal\Core\Database\Connection::dispatchEvent() is used to throw database API events.
  5. The method Drupal\Core\Database\Connection::findCallerFromDebugBacktrace() is used get the last non-database call from the debug backtrace data.
  6. The method Drupal\Core\Database\Connection::removeDatabaseEntriesFromDebugBacktrace() is used remove database calls from the debug backtrace data.

API deprecations:

  1. The method Drupal\Core\Database\Log::log() and is replaced by the new method Drupal\Core\Database\Log::logFromEvent().
  2. The method Drupal\Core\Database\Log::findCaller() and is replaced by the new method Drupal\Core\Database\Connection::findCallerFromDebugBacktrace()
  3. The method Drupal\Core\Database\Log::removeDatabaseEntries() and is replaced by the new method Drupal\Core\Database\Connection::removeDatabaseEntriesFromDebugBacktrace()
  4. The method Drupal\Core\Database\Log::getDebugBacktrace() and there is no replacement.
  5. Data model changes

    None.

    Release notes snippet

    Improved performance tracing and debugging capabilities of the database layer by allowing events to be triggered on statement execution. See the related change record โ†’ for a full description of this enhancement.

โœจ Feature request
Status

Fixed

Version

10.1 โœจ

Component
Databaseย  โ†’

Last updated about 1 hour ago

  • Maintained by
  • ๐Ÿ‡ณ๐Ÿ‡ฑNetherlands @daffie
Created by

๐Ÿ‡บ๐Ÿ‡ธUnited States mfb San Francisco

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

Comments & Activities

Not all content is available!

It's likely this issue predates Contrib.social: some issue and comment data are missing.

  • Status changed to RTBC over 1 year ago
  • Assigned to mondrake
  • Status changed to Needs work over 1 year ago
  • Issue was unassigned.
  • Status changed to Needs review over 1 year ago
  • Status changed to RTBC over 1 year ago
  • ๐Ÿ‡ณ๐Ÿ‡ฑNetherlands daffie

    Adding the ID of the StatementInterface object as returned by spl_object_id() is to me a good idea.
    There is testing added for the extra functionality.
    Back to RTBC.

  • ๐Ÿ‡บ๐Ÿ‡ธUnited States mfb San Francisco

    Wow this is amazing, thanks for running w/ this feature request! I'm now able to monitor db queries as they execute and build a nice hierarchical view of operations - see attached screenshot. I noticed that database logging didn't work until I cleared caches (not really a problem, just saying).

  • ๐Ÿ‡บ๐Ÿ‡ธUnited States mfb San Francisco

    Added a little release note snippet, feel free to edit.

  • ๐Ÿ‡ฎ๐Ÿ‡นItaly mondrake ๐Ÿ‡ฎ๐Ÿ‡น

    #35 nice!

  • ๐Ÿ‡ฌ๐Ÿ‡งUnited Kingdom catch

    #35 looks exciting! Adding tags for release notes + highlights. Haven't reviewed this enough to be able to commit it yet. What I did review didn't raise any massive flags - don't see a way around the \Drupal:: calls, and making it conditional on events being enabled at all is a good plan.

  • ๐Ÿ‡ฎ๐Ÿ‡นItaly mondrake ๐Ÿ‡ฎ๐Ÿ‡น

    Rerolled.

    • catch โ†’ committed d7313cce on 10.1.x
      Issue #3313355 by mondrake, mfb, Anchal_gupta, daffie, larowlan,...
  • Status changed to Fixed over 1 year ago
  • ๐Ÿ‡ฌ๐Ÿ‡งUnited Kingdom catch

    This will also be useful for ๐ŸŒฑ Automated performance testing for core Active , not that it's anywhere close but I've started working on it again after a decade.

    Reviewed again and couldn't find anything to complain about. Going to untag for release notes because there's nothing really for site owners here, but we can leave it tagged for highlights as an API improvement - can always drop it later.

    Committed d7313cc and pushed to 10.1.x. Thanks!

  • ๐Ÿ‡ฆ๐Ÿ‡บAustralia kim.pepper ๐Ÿ„โ€โ™‚๏ธ๐Ÿ‡ฆ๐Ÿ‡บSydney, Australia

    Created ๐Ÿ“Œ Create span for database execution Fixed for OpenTelemetry.

  • ๐Ÿ‡ฎ๐Ÿ‡นItaly mondrake ๐Ÿ‡ฎ๐Ÿ‡น

    Filed โœจ Add transaction-related events to the Database API Needs work for follow-up.

  • ๐Ÿ‡บ๐Ÿ‡ธUnited States mfb San Francisco

    Is enabling logging the only way to automatically enable events on all new connections? (If so, ideally we could make it easier to enable events without logging.)

    Database::openConnection() has

        if (!empty(self::$logs[$key])) {
          $new_connection->enableEvents([
            StatementExecutionStartEvent::class,
            StatementExecutionEndEvent::class,
          ]); 

    Btw, I noticed a typo in the change record which I'll fix:

    Calling code needs to opt-in for event dispatching by calling ::enableStatementEvents(TRUE) on the database Connection object.

    should be

    Calling code needs to opt-in for event dispatching by calling ::enableEvents(TRUE) on the database Connection object.
  • Automatically closed - issue fixed for 2 weeks with no activity.

Production build 0.69.0 2024