Problem/Motivation
Together with the duration of a database query, it would be great to make available the start time of the query when getting the database logs. This is already available in the query statement that performs the logging action so it doesn't add any overhead.
This is useful, for example, when logging the query in APM tools such as with the Elastic APM module. With start time + duration we have the full information about the query that otherwise is incomplete.
Proposed resolution
Add the start time of the query to the database log.
Remaining tasks
Commit
User interface changes
None
API changes
Added a new parameter start
to the method Drupal\Core\Database\Log::log()
.
Data model changes
None
Release notes snippet
TBD
Together with the duration of a database query, it would be great to make available the start time of the query when getting the database logs. This is already available in the query statement that performs the logging action so it doesn't add any overhead.
This is useful, for example, when logging the query in APM tools such as with the Elastic APM module. With start time + duration we have the full information about the query that otherwise is incomplete.
Comment | File | Size | Author |
---|---|---|---|
#30 | sql tracing.png | 379.63 KB | mfb |
#24 | 3089326-24.patch | 4.64 KB | ayushmishra206 |
#24 | interdiff_21-24.txt | 726 bytes | ayushmishra206 |
Comments
Comment #2
krystalcode CreditAttribution: krystalcode at Acro Commerce commentedComment #3
krystalcode CreditAttribution: krystalcode at Acro Commerce commentedPlease review.
Not sure if this function is called anywhere else, couldn't find.
Also, not sure if that's an API change and it would need to go to a different release.
Comment #5
daffie CreditAttribution: daffie commentedNew parameters should be added after all the existing ones. Also it must have a default value. Not doing so will result in a BC break.
Comment #6
ravi.shankar CreditAttribution: ravi.shankar at OpenSense Labs commentedHere I have re-rolled the patch #2.
Comment #7
agrochal CreditAttribution: agrochal at Google Code-In commentedI just set parameters in correct order, because as mentioned in #5 we should change the order but not only in Log.php but Statement.php also. Attaching patch and interdiff as well.
Comment #8
daffie CreditAttribution: daffie commented@agrochal: Good fix, thanks.
Now we just need those tests to be added.
Comment #10
mfbRerolled patch, added some missing changes that were needed, added a default value of the new parameter for backward compatibility, and added a basic test.
(I'd love to get this in so I can add some performance tracing UI improvements elsewhere... :)
Comment #11
mfb[deleted - wrong thread]
Comment #12
mfbComment #13
daffie CreditAttribution: daffie commented@mfb: Thank you for working on this patch. Just 2 points left for me:
I do not understand why this line is added. Can it be removed?
The new key "start" needs to be added here.
Comment #14
mfbI was using it to test that each start time in the array is greater than (or equal to) the previous start time, but I removed it as it's not necessary in my opinion.
Ok, good catch
Comment #15
daffie CreditAttribution: daffie commentedWhat is now the default value? NULL or 0?
Comment #16
mfbNot sure what you're saying needs work. Maybe you see an inconsistency here?
I made the default value NULL - i.e. this parameter is nullable - because 0 means midnight 1/1/1970 so isn't really suitable as a default value. There should always be a start time, but if somehow there is not, it's best to leave it unset.
The docblock is providing the "structure" of the array, not default values (some params do not have default values). The time and start elements do not default to zero; presumably the zero just indicated numeric.
Comment #17
daffie CreditAttribution: daffie commented@mfb: Good point.
All code changes look good to me.
I have added a CR and updated the IS.
For me it is RTBC.
Comment #18
mfb👍 CR looks good, thanks daffie
Comment #19
alexpottThis is missing a typehint. Since we're adding a parameter we can take the opportunity to properly typehint it - also the @param should have a float. Yes the rest of the documentation could do with being fixed but that's for another issue.
Comment #20
ankithashettyUpdated the patch in #14 addressing #19. Thank you!
Comment #21
ankithashettyUpdated patch.
Comment #22
daffie CreditAttribution: daffie commentedThe point of @alexpott has been addressed.
Back to RTBC.
Comment #23
alexpottThis should be:
StatementInterface $statement, $args, $time, float $start = NULL
We can't add the other typehints because that's a BC break.
I think it is fine to fix the @param typehints for the other parameters here although it is strictly out-of-scope.
Comment #24
ayushmishra206 CreditAttribution: ayushmishra206 at OpenSense Labs commentedMade the change suggested in #24. Please review.
Comment #25
ayushmishra206 CreditAttribution: ayushmishra206 at OpenSense Labs commentedComment #26
daffie CreditAttribution: daffie commentedThe point of @alexpott has been addressed.
Back to RTBC.
Comment #27
alexpottCommitted c377d26 and pushed to 9.2.x. Thanks!
Comment #30
mfbHere's a sample display of database query trace now that we are logging query start time: