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

[praveer38]

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

Superset.and.58.more.pages.-.Work.-.Microsoft_.Edge.2024-11-11.19-52-02.mp4

Superset version

4.0.2

Python version

3.9

Node version

16

Browser

Chrome

Additional context

No response

Checklist

• I have searched Superset docs and Slack and didn't find a solution to my problem.
• I have searched the GitHub issue tracker and didn't find a similar bug report.
• 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.

[dosubot]

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.

[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)

superset/superset-frontend/src/pages/QueryHistoryList/index.tsx

Lines 232 to 249 in 24b8a94

	Header: t('Duration'),
	size: 'xl',
	Cell: ({
	row: {
	original: { status, start_time, end_time },
	},
	}: any) => {
	const timerType = status === QueryState.Failed ? 'danger' : status;
	const timerTime = end_time
	? moment(moment.utc(end_time - start_time)).format(TIME_WITH_MS)
	: '00:00:00.000';
	return (
	<TimerLabel type={timerType} role="timer">
	{timerTime}
	</TimerLabel>
	);
	},
	},

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