Dolt start time of queries in logs is all pinned to the connection open start time

[timsehn]

INFO[1669] NewConnection                                 DisableClientMultiStatements=false connectionID=24
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SET NAMES utf8mb3"
DEBU[1669] Query finished in 0 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SET NAMES utf8mb3"
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SET autocommit=0"
DEBU[1669] Query finished in 0 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SET autocommit=0"
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SET autocommit=1"
DEBU[1669] Query finished in 0 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SET autocommit=1"
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SELECT VERSION(), @@sql_mode, @@default_storage_engine, @@sql_auto_is_null, @@lower_case_table_names, CONVERT_TZ('2001-01-01 01:00:00', 'UTC', 'UTC') IS NOT NULL"
DEBU[1669] Query finished in 0 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SELECT VERSION(), @@sql_mode, @@default_storage_engine, @@sql_auto_is_null, @@lower_case_table_names, CONVERT_TZ('2001-01-01 01:00:00', 'UTC', 'UTC') IS NOT NULL"
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED"
DEBU[1669] Query finished in 0 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED"
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="CALL DOLT_CHECKOUT('main')"
DEBU[1669] Query finished in 0 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="CALL DOLT_CHECKOUT('main')"
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SELECT `polls_question`.`id`, `polls_question`.`question_text`, `polls_question`.`pub_date` FROM `polls_question` WHERE `polls_question`.`id` = 3 LIMIT 21"
DEBU[1669] Query finished in 0 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SELECT `polls_question`.`id`, `polls_question`.`question_text`, `polls_question`.`pub_date` FROM `polls_question` WHERE `polls_question`.`id` = 3 LIMIT 21"
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SELECT `polls_choice`.`id`, `polls_choice`.`question_id`, `polls_choice`.`choice_text`, `polls_choice`.`votes` FROM `polls_choice` WHERE (`polls_choice`.`question_id` = 3 AND `polls_choice`.`id` = 7) LIMIT 21"
DEBU[1669] Query finished in 0 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="SELECT `polls_choice`.`id`, `polls_choice`.`question_id`, `polls_choice`.`choice_text`, `polls_choice`.`votes` FROM `polls_choice` WHERE (`polls_choice`.`question_id` = 3 AND `polls_choice`.`id` = 7) LIMIT 21"
DEBU[1669] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="UPDATE `polls_choice` SET `question_id` = 3, `choice_text` = 'Yes', `votes` = 3 WHERE `polls_choice`.`id` = 7"
DEBU[1669] Query finished in 6 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="UPDATE `polls_choice` SET `question_id` = 3, `choice_text` = 'Yes', `votes` = 3 WHERE `polls_choice`.`id` = 7"
DEBU[1800] starting statistics refresh check for 'mydatabase': 2025-02-28 13:03:17.701117 -0800 PST m=+1800.251477585 
DEBU[1800] statistics refresh: new table hash: 52qkcc17dcqtblc9aml4so2jrooun338 
DEBU[1800] statistics refresh index: mydatabase.auth_group.primary 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh index: mydatabase.auth_group.name 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh: new table hash: 52qkcc17dcqtblc9aml4so2jrooun338 
DEBU[1800] statistics refresh index: mydatabase.auth_group_permissions.primary 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh index: mydatabase.auth_group_permissions.auth_group_permissio_permission_id_84c5c92e_fk_auth_perm 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh index: mydatabase.auth_group_permissions.auth_group_permissions_group_id_permission_id_0cd325b0_uniq 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh: table hash unchanged since last check: 0rrhihosaq4tp2i2g3g2h0of0j4arngr 
DEBU[1800] statistics refresh: table hash unchanged since last check: kbvcht8nf94hp69pr3chkkkh4n00lkrs 
DEBU[1800] statistics refresh: new table hash: 52qkcc17dcqtblc9aml4so2jrooun338 
DEBU[1800] statistics refresh index: mydatabase.auth_user_groups.primary 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh index: mydatabase.auth_user_groups.auth_user_groups_group_id_97559544_fk_auth_group_id 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh index: mydatabase.auth_user_groups.auth_user_groups_user_id_group_id_94350c0c_uniq 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh: new table hash: 52qkcc17dcqtblc9aml4so2jrooun338 
DEBU[1800] statistics refresh index: mydatabase.auth_user_user_permissions.primary 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh index: mydatabase.auth_user_user_permissions.auth_user_user_permi_permission_id_1fbb5f2c_fk_auth_perm 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh index: mydatabase.auth_user_user_permissions.auth_user_user_permissions_user_id_permission_id_14a6b632_uniq 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh: table hash unchanged since last check: dih3csddgjipvcr2hop25miv97olsh6k 
DEBU[1800] statistics refresh: table hash unchanged since last check: fckpuml4e39ks2sa20dthijr0nb2n2fo 
DEBU[1800] statistics refresh: table hash unchanged since last check: rjmgraadtkge155uoo1t6f9juatq3hti 
DEBU[1800] statistics refresh: new table hash: 0jk3p0sq4pabpaol66jmtvauncl8e1oj 
DEBU[1800] statistics refresh index: mydatabase.django_session.primary 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh index: mydatabase.django_session.django_session_expire_date_a5c62663 
DEBU[1800] statistics current: 0, new: 0, delete: 0     
DEBU[1800] statistics refresh: new table hash: u1776o5umrrda3nfiamn31e1fekuiegs 
DEBU[1800] statistics refresh index: mydatabase.polls_choice.primary 
DEBU[1800] statistics current: 1, new: 1, delete: 1     
DEBU[1800] statistics updating: mydatabase.polls_choice.primary 
DEBU[1800] statistics refresh index: mydatabase.polls_choice.polls_choice_question_id_c5b4b260_fk_polls_question_id 
DEBU[1800] statistics current: 1, new: 0, delete: 0     
DEBU[1800] statistics refresh: table hash unchanged since last check: je3h7egeb3uskdabob2tpdoper45d5c6 
DEBU[1969] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="CALL DOLT_COMMIT('-Am', 'Modified database in Django. Creating Dolt Commit.')"
DEBU[1969] Query finished in 19 ms                       connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="CALL DOLT_COMMIT('-Am', 'Modified database in Django. Creating Dolt Commit.')"

Basically, between:

DEBU[1669] Query finished in 6 ms                        connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="UPDATE `polls_choice` SET `question_id` = 3, `choice_text` = 'Yes', `votes` = 3 WHERE `polls_choice`.`id` = 7"

and:

DEBU[1969] Starting query                                connectTime="2025-02-28 13:01:06.629351 -0800 PST m=+1669.180382710" connectionDb=mydatabase connectionID=24 query="CALL DOLT_COMMIT('-Am', 'Modified database in Django. Creating Dolt Commit.')"

There was a 5 minute sleep as indicated by the stats running.

I guess the log line does say connect time but I think we want query start time here.