Fix inconsistent logging unit for SQL query duration reporting microseconds instead of milliseconds

[pritesh-4]

Description

There is a duration unit inconsistency in the SQL datasource query logging. The console logger formats query execution latency with a µs (microsecond) suffix, but the underlying duration value is calculated in milliseconds.
Other datasources within GoFr (such as Redis, MongoDB, Cassandra, ClickHouse, and SurrealDB) correctly calculate query latency in microseconds and format them with µs.

Steps to Reproduce

1. Configure any GoFr application with a SQL database (e.g. SQLite, PostgreSQL, or MySQL).
2. Execute a fast database query (e.g., SELECT 1 or fetching a small row by ID).
3. Check the output logs in the terminal.

Observed Logs:

(Even when the query takes hundreds of microseconds to execute).
If a query takes exactly 15 milliseconds, it is logged as:

---

Expected Behavior

The query latency logs should report accurate duration in microseconds, matching the rest of GoFr's datasources:

• A query taking 15 milliseconds should be logged as 15000µs (or 15.0ms if using milliseconds).
• A sub-millisecond query taking 500 microseconds should be logged as 500µs.

---

Actual Behavior

The SQL datasource logs milliseconds under the microsecond (µs) unit label, causing a 1000x under-reporting and truncating sub-millisecond queries to 0µs.

---

Root Cause

In pkg/gofr/datasource/sql/db.go, the helper function sendStats calculates query execution duration in milliseconds:

func sendStats(logger datasource.Logger, metrics Metrics, config *DBConfig, start time.Time, queryType, query string, args ...any) {
	duration := time.Since(start).Milliseconds()
    // ...

[adarshjnv9100]

Hi @pritesh-4,

I’d like to work on this issue and would appreciate it if you could assign it to me.

I’ve gone through the issue and understand the root cause and the expected fix. My plan is:

1. Investigate the existing SQL logging flow

   • Review pkg/gofr/datasource/sql/db.go, especially the sendStats helper.
   • Trace how query execution time is calculated and passed to the logger/metrics.
   • Compare the implementation with other datasources such as Redis, MongoDB, Cassandra, ClickHouse, and SurrealDB to ensure consistency.

2. Fix the duration unit mismatch

   • The current implementation uses:
     time.Since(start).Milliseconds()
   • Since the log output uses the µs suffix, I’ll change the duration calculation to use microseconds:
     time.Since(start).Microseconds()
   • This will ensure that the logged value actually represents microseconds and preserves sub-millisecond query durations.

3. Check the surrounding logging/metrics behavior

   • Verify that changing the unit does not unintentionally affect metrics, interfaces, or other consumers of the duration value.
   • Ensure the change is limited to the SQL datasource behavior described in this issue.

4. Add/update tests

   • Add test coverage for query durations that are:

     • sub-millisecond, e.g. ~500µs
     • several milliseconds, e.g. ~15ms

   • Verify that the logged duration and µs unit are consistent.

   • Make sure existing SQL datasource tests continue to pass.

5. Run the relevant test suite

   • Run the SQL datasource tests.
   • Run the broader GoFr test suite if practical.
   • Run formatting/linting checks before submitting the PR.

6. Submit a focused PR

   • Keep the change minimal and limited to the duration unit inconsistency.
   • Include the test changes and clearly mention that the fix prevents the current 1000x under-reporting and 0µs truncation for sub-millisecond queries.

I’m happy to take this up. Please assign the issue to me. Thanks!

[subhadip2004999]

Hi maintainers, I would love to work on this issue. Could you please assign it to me?