Include query execution time
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	Slaporte
	Feb 13 2016, 8:59 PM

Description

Add in worker.py the count of query running time (delta of before/after execution timers) and store it in a new column of the query_run table.
Then show this in query run info api endpoint then in the nunchunk-created interface.

Details

	Subject	Repo	Branch	Lines +/-
	worker.py: fix running time calculation points	analytics/quarry/web	master	+1 -1
	Store and show query execution time	analytics/quarry/web	master	+8 -3

Customize query in gerrit

Related Objects
Search...

		Status	Subtype	Assigned	Task
		Resolved		Stibba	T71264 Show execution time in the Recent Queries page
		Resolved		Framawiki	T126888 Include query execution time

Event Timeline

Slaporte created this task.Feb 13 2016, 8:59 PM

Slaporte raised the priority of this task from to Needs Triage.

Slaporte updated the task description. (Show Details)

Slaporte added a project: Quarry.

Slaporte added subscribers: Slaporte, mahmoud, yuvipanda.

Restricted Application added subscribers: StudiesWorld, Aklapper. · View Herald TranscriptFeb 13 2016, 8:59 PM

+1 ! :)

XXN awarded a token.Apr 17 2016, 11:05 AM

matej_suchanek merged tasks: T136266: show time of execution in quarry, T135189: Display time taken to execute a query.May 28 2016, 8:43 PM

matej_suchanek added a parent task: T71264: Show execution time in the Recent Queries page.

matej_suchanek added subscribers: Zppix, Yamaha5, TerraCodes, Matthewrbowker.

He7d3r awarded a token.May 29 2016, 2:19 AM

He7d3r added a subscriber: He7d3r.

matej_suchanek awarded a token.May 29 2016, 7:20 AM

matej_suchanek added a subscriber: matej_suchanek.

Yamaha5 awarded a token.Jun 1 2016, 4:45 AM

Yamaha5 moved this task from Backlog to Planning on the Quarry board.

zhuyifei1999 added a subscriber: zhuyifei1999.Jun 20 2016, 1:13 PM

Lokal_Profil awarded a token.Oct 21 2016, 9:22 AM

Lokal_Profil added a subscriber: Lokal_Profil.

• Phabricator_maintenance removed a subscriber: yuvipanda.Jun 7 2017, 6:44 PM

zhuyifei1999 merged a task: T172082: Quarry should store the query runtime along with the results.Jul 31 2017, 1:03 AM

zhuyifei1999 added a subscriber: Huji.

Huji updated the task description. (Show Details)Jul 31 2017, 1:07 AM

See also T77941

• Capt_Swing added a subscriber: • Capt_Swing.Aug 7 2017, 8:58 PM

Framawiki merged a task: T71264: Show execution time in the Recent Queries page.Apr 16 2018, 9:49 PM

zhuyifei1999 merged a task: T206480: Store and show query execution time.Oct 8 2018, 7:02 PM

zhuyifei1999 added a subscriber: Framawiki.

I don't seen any benefit of adding the pending time (only for monitoring purposes?), feel free to explain why it's needed

The only advantage would be to know if queries are getting stuck in "pending" mode for too long. It used to be an issue a while back but hasn't been for a long time.

It was probably T172143: Weird race condition makes query stuck in queued forever. It would stay pending anyhow.

Change 465659 had a related patch set uploaded (by Framawiki; owner: Framawiki):
[analytics/quarry/web@master] Store and show query execution time

https://gerrit.wikimedia.org/r/465659

gerritbot added a project: Patch-For-Review.Oct 10 2018, 4:56 PM

Change 465659 merged by jenkins-bot:
[analytics/quarry/web@master] Store and show query execution time

https://gerrit.wikimedia.org/r/465659

Mentioned in SAL (#wikimedia-cloud) [2018-10-15T18:52:53Z] <framawiki> deployed c1dfde7 on quarry-web-01, quarry-worker-0{1,2} T126888

Queries now show execution time near the resultset on the status page.

zhuyifei1999 awarded a token.Oct 15 2018, 6:58 PM

@Framawiki: I think using using the time of cur.execute to get the execution time is flawed. There is no way this query could finish in 0.01 seconds.

Tested with https://quarry.wmflabs.org/query/30399:

SELECT SLEEP(10);

waits for completion in cur.execute(), while

USE enwiki_p;
SELECT SLEEP(10);

doesn't.

It would be nice to have both execute time and combined execute + fetch time, as the latter more accurately represents the an application would spend waiting (which would really help with prototyping). Also, thanks for this!

I guess we could just change to execute + fetch + store. Beware though, that can be heavily lagged due to the use of SQLite on NFS for storing the results.

I currently don't see a way of forcing pymysql to finish the query before returning from cur.execute, without putting all the results into memory (which we kinda do anyways)

Change 468826 had a related patch set uploaded (by Framawiki; owner: Framawiki):
[analytics/quarry/web@master] worker.py: fix running time calculation points

https://gerrit.wikimedia.org/r/468826

Thanks for checking that it works @zhuyifei1999 ! I should have tested with sleep, that's how I see that I'm a volunteer here :)
The patch above move the stoppoint after all the worker process (execute + fetch + store).