Query start time in database log

1. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -106,16 +106,21 @@ public function end($logging_key) {
   -  public function log(StatementInterface $statement, $args, $time) {
   +  public function log(StatementInterface $statement, $args, $start, $time) {
   

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

2. We need testing for this to make sure it works and that it keep working in the future.

Here I have re-rolled the patch #2.

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

@agrochal: Good fix, thanks.

Now we just need those tests to be added.

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

[deleted - wrong thread]

@mfb: Thank you for working on this patch. Just 2 points left for me:

1. +++ b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php
   @@ -32,6 +33,9 @@ public function testEnableLogging() {
   +      $start = $query['start'];
   

   I do not understand why this line is added. Can it be removed?

2. In the file core/lib/Drupal/Core/Database/Log.php, we have the following docblock:

     /**
      * Cache of logged queries. This will only be used if the query logger is enabled.
      *
      * The structure for the logging array is as follows:
      *
      * array(
      *   $logging_key = array(
      *     array('query' => '', 'args' => array(), 'caller' => '', 'target' => '', 'time' => 0),
      *     array('query' => '', 'args' => array(), 'caller' => '', 'target' => '', 'time' => 0),
      *   ),
      * );
      *
      * @var array
      */
     protected $queryLog = [];
   

   The new key "start" needs to be added here.

I do not understand why this line is added. Can it be removed?

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

The new key "start" needs to be added here.

Ok, good catch

+++ b/core/lib/Drupal/Core/Database/Log.php
@@ -22,8 +22,8 @@ class Log {
+   *     array('query' => '', 'args' => array(), 'caller' => '', 'target' => '', 'time' => 0, 'start' => 0),
+   *     array('query' => '', 'args' => array(), 'caller' => '', 'target' => '', 'time' => 0, 'start' => 0),

@@ -108,9 +108,13 @@ public function end($logging_key) {
+  public function log(StatementInterface $statement, $args, $time, $start = NULL) {

What is now the default value? NULL or 0?

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

@mfb: Good point.

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

👍 CR looks good, thanks daffie

+++ b/core/lib/Drupal/Core/Database/Log.php
@@ -108,9 +108,13 @@ public function end($logging_key) {
+   * @param $start
+   *   The time the query started as a float (in seconds since the Unix epoch
+   *   with microsecond precision).
    */
-  public function log(StatementInterface $statement, $args, $time) {
+  public function log(StatementInterface $statement, $args, $time, $start = NULL) {

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

Updated the patch in #14 addressing #19. Thank you!

Updated patch.

The point of @alexpott has been addressed.
Back to RTBC.

+++ b/core/lib/Drupal/Core/Database/Log.php
@@ -114,7 +114,7 @@
-  public function log(StatementInterface $statement, $args, $time, $start = NULL) {
+  public function log(StatementInterface $statement, array $args, float $time, float $start = NULL) {

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

Made the change suggested in #24. Please review.

The point of @alexpott has been addressed.
Back to RTBC.

Committed c377d26 and pushed to 9.2.x. Thanks!

Here's a sample display of database query trace now that we are logging query start time: