Bug description

On the SQL Lab’s “Query History” tab, the “Duration column:

expected: it should show only execution duration for the query (i.e. under a second for simple queries)

actual: it is showing some real values along with some unexpected values as shown in the video and screenshot.

Steps to Reproduce

  1. Go to SQL Lab
  2. Create a query
  3. Run the query (and variations of it) multiple times
  4. Click the “Query History” tab
  5. The “Duration” column will show a fraction of a second for each query
  6. In the Results column, click “View”
  7. Close the query view

Screenshots/recordings

Apache Superset SQL Lab: Query History: Duration column shows some nonsense durations (expected only duration of run)

https://github.com/user-attachments/assets/6c952b9c-f612-4478-996e-ab2531d2c41a

Superset version

4.0.2

Python version

3.9

Node version

16

Browser

Chrome

Additional context

No response

Checklist

  • [X] I have searched Superset docs and Slack and didn't find a solution to my problem.
  • [X] I have searched the GitHub issue tracker and didn't find a similar bug report.
  • [X] I have checked Superset's logs for errors and if I found a relevant Python stacktrace, I included it here as text in the "additional context" section.

Comment From: dosubot[bot]

The "Duration" column in the SQL Lab's "Query History" tab shows unexpected values because it calculates the duration using both the start and end timestamps of the query execution. The duration is computed using the fDuration function, which takes q.startDttm and q.endDttm as inputs. This means that the duration reflects the total time from when the query started to when it ended, which may include time spent in states other than just execution, such as queuing or waiting for resources [1].

The fDuration function calculates the duration by subtracting the start time from the end time to get the difference in milliseconds, then formats it as a UTC time string [2].

The possible states a query can be in during its lifecycle include Started, Stopped, Failed, Pending, Running, Scheduled, Success, Fetching, and TimedOut. The startDttm is set when the query enters the Started state, and endDttm is set when the query reaches a concluded state, such as Stopped, Failed, Success, or TimedOut [3].

To continue talking to Dosu, mention @dosu.

Comment From: rusackas

Here's where that value is calculated/displayed, if you want to debug things a bit (printing out the times used in the calculation, etc) https://github.com/apache/superset/blob/24b8a94c2ce4d21c65caa076bdc54ba61635be85/superset-frontend/src/pages/QueryHistoryList/index.tsx#L232-L249

Comment From: rusackas

Is this still an issue in 4.1.2/5.0.0/master? This has been silent for quite a while, but it's the kind of bug we don't want to sweep under the rug if it's still happening. It's at risk of being closed as inactive otherwise.

Comment From: rusackas

Opened a PR!