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.

Issue fork drupal-3313355

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

mfb created an issue. See original summary.

anchal_gupta’s picture

StatusFileSize
new5.99 KB
new575 bytes

I have fix CS error. Please review it

mfb’s picture

Thanks @Anchal_gupta for the quick typo fix! Hiding the failed patch

larowlan’s picture

I wonder if this is something that meets the 80% use-case, or is it better kept as a patch that someone could apply for when they need additional logging of database logs, but otherwise not run in production (as in itself it adds a performance overhead)

+++ b/core/lib/Drupal/Core/Database/Log.php
@@ -31,6 +37,13 @@ class Log {
+  protected $eventDispatcher = [];

@@ -57,11 +70,15 @@ public function __construct($key = 'default') {
+    $this->eventDispatcher[$logging_key] = $event_dispatcher;

Do we need an array of event dispatchers? wouldn't there ever only be the one service from core?

larowlan’s picture

Status: Needs review » Postponed (maintainer needs more info)
mfb’s picture

Status: Postponed (maintainer needs more info) » Needs review
Issue tags: +Contributed project soft blocker

I'd really like to get something like this into core so that my Sentry integration (Raven module) - which is running on over 4k Drupal sites - can build a hierarchical view of span operations when performance tracing is enabled. Currently this is doable for most operations, like template rendering, but for database queries I just have a flat, non-hierarchical list of queries added at the end of the request/execution, since the db layer doesn't have a middleware or fire events (unlike some db layers elsewhere :).

A site might even run Sentry performance tracing in production, at least occasionally, with a low sample rate. And I don't want to provide functionality that requires hacking core if I can avoid it.

As far as I can tell, there's basically no performance overhead here, unless a module enables database logging and injects the event dispatcher. Once your module disables logging, no more events are fired. In fact there could even be less logging overhead with the patch, as there would be no need to store a query log when a logger injects the event dispatcher.

I created an array to store the event dispatcher because there could be multiple loggers on the database. Currently the loggers and their logs are all stored in an array. But in this case, I want to store a logger and whether or not it wants to use the event dispatcher, and provide modules a way to inject the event dispatcher when setting up logging. This way, each logger can manage how it works - whether it wants to store the query log in an array (the default) or receive events. The array of event dispatchers are of course just references. But if it seems cleaner, I could refactor this to allow logging modules to inject the event dispatcher, and store just one reference to the event dispatcher; I guess there would have to be at least an array of booleans to indicate that the logger wants to use the event dispatcher rather than query log.

Note - there would ideally be a lot more different kinds of events fired, such as starting a transaction, rolling back a transaction, etc. - but I wanted to at least replicate the existing query logging as events.

Setting back to needs review to get any more thoughts on this, but I could also do some refactoring in the near future..

mondrake’s picture

It's a nice idea.

I think the first hurdle would be to agree that we add an event system to the Database API. It would make a lot of sense to me in 2022.

Then, IMHO if we move in this direction it would be better to completely swap the current logging facility with a series of events (fired at statement execution start, at statement execution end, etc ...) dispatched to the container's event_dispatcher, and convert the current logging to an event subscriber instead (i.e. for it to become one of the possible ways to trace SQL execution).

Certainly performance impact should be assessed, this would be running on low level code; in my understanding SQL logging was meant so far more or less for debugging only, an use case like #6 would open up for it to be used in real time monitoring of prod sites.

mfb’s picture

On my laptop - not an ideal benchmarking scenario, there was a fair amount of variability - it looks like the existing database query log processing (getting the query string, finding the caller from the backtrace, etc.), plus creating an event and then dispatching it, adds ~22.5 microseconds to a query, which added 18 milliseconds to my test page with 791 database queries. Of this, building the event data is ~20 microseconds and the dispatch() call itself is ~2.5 microseconds.

It's not a terribly huge amount of milliseconds, but given how database-heavy a drupal site could be - especially if caches are using the database - I would say it makes sense for event dispatching to be opt-in, similar to how the existing database query log works (but, probably cleaner to add a new static method to Database rather than shoehorning it into Database::startLog()). I'm not trying to decrease performance by default here, just trying to give site admins tools to measure performance (and generally with a low sample rate so most page loads are not affected).

mfb’s picture

StatusFileSize
new4.41 KB
new3.86 KB

I do like @mondrake's idea in #7 of having a way to enable events in the db layer, and overhauling loggers to be event subscribers.

In the meantime, here's a simplified version of my initial patch. The logger object now simply fires an event if the eventDispatcher property has been set. There's no need to patch \Drupal\Core\Database\Database class; any code calling Database::startLog() can simply call Log::setEventDispatcher() on the Log object returned by Database::startLog() to start receiving events. This simple change would drop in nicely if there's no desire to rock the boat with regards to database logging, and I don't think there is a BC concern since I don't know how someone would extend the Log class.

mfb’s picture

Issue summary: View changes

Updating the API part of the issue summary.

mondrake’s picture

Assigned: Unassigned » mondrake

I'm working on a concept for #7.

mondrake’s picture

In the MR, some changes to implement events on the Statement objects in place of the logger, i.e. on very low level. It's a concept, if that seems the right direction then we'll have to make it work with changes and deprecations on higher levels.

daffie’s picture

Status: Needs review » Needs work

I like the idea of using events for logging and it is the Symfony way of doing this.
What for me is very important is that when logging is of, Drupal does not get a performance hit.
The MR from @mondrake is to me the solution we should go for.
I did a review on the MR and it looks good to me.
We need testing for this.

mondrake’s picture

Thanks for review @daffie.

Re. tests I was also wondering... we already have LogTest that covers logging, and it shows that the changes are BC since they end up with the same logging results. I wouldn't add tests that prove that event dispatching and subscribing works... they're not for here. Input welcome.

mondrake’s picture

added a draft placeholder CR and adjusted deprecations

daffie’s picture

@mondrake Can we add testing for the new method from Connection class and the method Log::logFromEvent(). The problem is that the deprecated tests from LogTest will be removed in D11.

mfb’s picture

Havent tried the MR yet but looking nice so far. Calling \Drupal::service() certainly makes things easier vs. injecting.

Would we add events for transaction start/commit/rollback in this issue or a followup?

mondrake’s picture

Status: Needs work » Needs review
Issue tags: -Needs tests

Added unit tests.

Would we add events for transaction start/commit/rollback in this issue or a followup?

In a follow-up, please. We need to land a first instalment of an event system connected to the database API, first. And IMHO we the smaller its scope, the higher the chances.

mondrake’s picture

Assigned: mondrake » Unassigned
daffie’s picture

Issue summary: View changes
Status: Needs review » Reviewed & tested by the community
Issue tags: -Needs change record updates, -Needs issue summary update

All code changes look good to me.
I have updated the IS and the CR.
Testing has been added.
For me it is RTBC.

mondrake’s picture

Thanks for filling in the CR, @daffie. I made a few changes, trying to make clear that statement exection events are not strictly bound to the logging (i.e. you can have events dispatched even if the logging is not enabled).

alexpott’s picture

Status: Reviewed & tested by the community » Needs work

Added a review to the MR.

mondrake’s picture

Assigned: Unassigned » mondrake

Thank you @alexpott. I will be on this; I also think we could do something more, too.

mondrake’s picture

Addressed @alexpott's review points in last commit.

Now planning to:

  • use S6.2 syntax for subscribing service
  • split event in two, one for execution start one and one for execution end - and use their FQCN as the event name instead - so to get rid of DatabaseEvents constants. In S6.2+, the event dispatch method requires an event object, and a literal name is optional: if not passed in, the FQCN is used https://github.com/symfony/symfony/blob/6.3/src/Symfony/Contracts/EventD...
  • make Connection::enableStatementEvents() and friends generic so that if other events are added later, we won't not need additional methods
mondrake’s picture

mondrake’s picture

Assigned: mondrake » Unassigned
Status: Needs work » Needs review
Issue tags: +Needs issue summary update, +Needs change record updates

Done #25.

Appreciated help to list what tests are missing at this point, as well as updates to IS and CR.

mondrake’s picture

Issue summary: View changes
Issue tags: -Needs issue summary update
mondrake’s picture

Added some Unit and Kernel tests for the new API. Also, Connection::dispatchEvent() now throws an exception if the container is not initialized yet.

daffie’s picture

@mondrake: I have just one question: Why is the StatementExecutionStartEvent not dispatched in core/lib/Drupal/Core/Database/StatementPrefetch.php and core/lib/Drupal/Core/Database/StatementWrapper.php and StatementExecutionEndEvent is dispatched? Ok, my bad. I missed the part $this->connection->dispatchEvent($startEvent);.
The rest of the MR looks great.

daffie’s picture

Status: Needs review » Reviewed & tested by the community
Issue tags: -Needs change record updates

All remarks of @alexpott has been addressed or answered.
The CR has been updated.
Back to RTBC.

mondrake’s picture

Assigned: Unassigned » mondrake
Status: Reviewed & tested by the community » Needs work

Self reviewing, I think we could try using spl_object_id to relate independent event objects to the same statement object. Would be relevant for multi-thread or multi-connection monitoring.

mondrake’s picture

Assigned: mondrake » Unassigned
Status: Needs work » Needs review
daffie’s picture

Status: Needs review » Reviewed & tested by the community

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.

mfb’s picture

StatusFileSize
new391.64 KB

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

mfb’s picture

Issue summary: View changes

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

mondrake’s picture

#35 nice!

catch’s picture

#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.

mondrake’s picture

Rerolled.

  • catch committed d7313cce on 10.1.x
    Issue #3313355 by mondrake, mfb, Anchal_gupta, daffie, larowlan,...
catch’s picture

Status: Reviewed & tested by the community » Fixed
Issue tags: -10.1.0 release notes

This will also be useful for #638078: Automated performance testing for core, 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!

kim.pepper’s picture

mondrake’s picture

mfb’s picture

Is enabling logging the only way to automatically enable events on 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.

Status: Fixed » Closed (fixed)

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