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:
-
The method
Drupal\Core\Database\Log::logFromEvent()adds database query loggings events data to the query log. -
The method
Drupal\Core\Database\Connection::isEventEnabled()returns the status of the database API events being dispatched. -
The methods
Drupal\Core\Database\Connection::enableEvents()andDrupal\Core\Database\Connection::disableEvents()enable or disable the dispatching of database API events. -
The method
Drupal\Core\Database\Connection::dispatchEvent()is used to throw database API events. -
The method
Drupal\Core\Database\Connection::findCallerFromDebugBacktrace()is used get the last non-database call from the debug backtrace data. -
The method
Drupal\Core\Database\Connection::removeDatabaseEntriesFromDebugBacktrace()is used remove database calls from the debug backtrace data.
API deprecations:
-
The method
Drupal\Core\Database\Log::log()and is replaced by the new methodDrupal\Core\Database\Log::logFromEvent(). -
The method
Drupal\Core\Database\Log::findCaller()and is replaced by the new methodDrupal\Core\Database\Connection::findCallerFromDebugBacktrace() -
The method
Drupal\Core\Database\Log::removeDatabaseEntries()and is replaced by the new methodDrupal\Core\Database\Connection::removeDatabaseEntriesFromDebugBacktrace() -
The method
Drupal\Core\Database\Log::getDebugBacktrace()and there is no replacement. -
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.
| Comment | File | Size | Author |
|---|
Issue fork drupal-3313355
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:
- 3313355-allow-the-database
changes, plain diff MR !3137
Comments
Comment #2
anchal_gupta commentedI have fix CS error. Please review it
Comment #3
mfbThanks @Anchal_gupta for the quick typo fix! Hiding the failed patch
Comment #4
larowlanI 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)
Do we need an array of event dispatchers? wouldn't there ever only be the one service from core?
Comment #5
larowlanComment #6
mfbI'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..
Comment #7
mondrakeIt'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.
Comment #8
mfbOn 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).Comment #9
mfbI 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.
Comment #10
mfbUpdating the API part of the issue summary.
Comment #11
mondrakeI'm working on a concept for #7.
Comment #13
mondrakeIn 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.
Comment #14
daffie commentedI 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.
Comment #15
mondrakeThanks for review @daffie.
Re. tests I was also wondering... we already have
LogTestthat 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.Comment #16
mondrakeadded a draft placeholder CR and adjusted deprecations
Comment #17
daffie commented@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.
Comment #18
mfbHavent 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?
Comment #19
mondrakeAdded unit tests.
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.
Comment #20
mondrakeComment #21
daffie commentedAll code changes look good to me.
I have updated the IS and the CR.
Testing has been added.
For me it is RTBC.
Comment #22
mondrakeThanks 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).
Comment #23
alexpottAdded a review to the MR.
Comment #24
mondrakeThank you @alexpott. I will be on this; I also think we could do something more, too.
Comment #25
mondrakeAddressed @alexpott's review points in last commit.
Now planning to:
Connection::enableStatementEvents()and friends generic so that if other events are added later, we won't not need additional methodsComment #26
mondrakeUse FQCN as the service name - precedent: #3327856-29: Performance regression introduced by container serialization solution
Comment #27
mondrakeDone #25.
Appreciated help to list what tests are missing at this point, as well as updates to IS and CR.
Comment #28
mondrakeComment #29
mondrakeAdded some Unit and Kernel tests for the new API. Also,
Connection::dispatchEvent()now throws an exception if the container is not initialized yet.Comment #30
daffie commented@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.
Comment #31
daffie commentedAll remarks of @alexpott has been addressed or answered.
The CR has been updated.
Back to RTBC.
Comment #32
mondrakeSelf 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.
Comment #33
mondrakeComment #34
daffie commentedAdding 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.
Comment #35
mfbWow 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).
Comment #36
mfbAdded a little release note snippet, feel free to edit.
Comment #37
mondrake#35 nice!
Comment #38
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.
Comment #39
mondrakeRerolled.
Comment #41
catchThis 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!
Comment #43
kim.pepperCreated #3348581: Create span for database execution for OpenTelemetry.
Comment #44
mondrakeFiled #3348590: Add transaction-related events to the Database API for follow-up.
Comment #45
mfbIs 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
Btw, I noticed a typo in the change record which I'll fix:
should be