560502 - [buildbot] Track the amount of time a change sits in the queue before buildbot starts building the change

Status: RESOLVED FIXED

(Tamarin Graveyard :: Tools, defect, P2)

Description

[Brent Baker]

We want to know for each change in tamarin-redux, argo and sandbox, how long does a change sit in the buildbot queue before it is submitted into the build.

One easy way to implement this would be to look at the <buildbot>/changes/processed directory and look at the timestamps on the build request files.

request time = create date
processed time = modified date

If the modified date is not changed when the file is moved from "pending" into "processed" then the watcher_trigger.py script (which moves the request file) can be modified to touch the file when it moves it.

Comment 1

[Trevor Baker]

Info should be logged to csv for later mining.  Columns could include date, branch (tr, tr-argo, sandbox, etc),  queue-time, revision

Comment 2

[James Sudduth]

Attachment: Pending build queue wait time logging.

Please review the changes in the processBatchedChanges function especially carefully as it wasn't possible to test this code well (lines 142-148).

Comment 3

[Brent Baker]

Comment on attachment 442024 [details] [diff] [review]
Pending build queue wait time logging.

- call to logQueueTimes() for the sandbox should only pass /change/ instead of priority3files as only ONE change file will be processed and not all of them:
   logQueueTimes(3, change, "sandbox")

+ Please comment out/remove this line in the except block, this was causing the process to crash and I have tweaked the current deployed version of the script but have NOT pushed the change back into source (my bad)
"log(sys.exc_info())"

+ wondering about the usefulness of the last column in the data. I assume that the expect reporting of this data will be in minutes so might as well just log that so that it can be used directly. Since full timestamps are being recorded somebody could still determine to the second the amount of time a request sat in the queue

Comment 4

[Trevor Baker]

Is this ready to go?

Comment 5

[James Sudduth]

I've made the first two changes Brent suggested and am awaiting review from Chris. I'm not sure how to incorporate the expect data, so I left the last column as is for now.

Comment 6

[Trevor Baker]

How often will the csv be updated?  In real time?  Will it generally readable or locked?  I'd like to be able to use the csv it in a confluence chart wrapped in a cache tag.

Comment 7

[Chris Peyer]

Comment on attachment 442024 [details] [diff] [review]
Pending build queue wait time logging.

I think that we should record total elapsed time between creating and processed in seconds instead of the hours/min/sec format.  That would make it easier to calculate and process/display the data programatically (though I guess we can just compute that from the current format).

Other than that and Brents suggestions - r+

Comment 8

[Trevor Baker]

From the confluence chart and csv perspective, I can't do any operations on the values.  Could there be a column for seconds (as Chris suggests) and another for minutes (maybe with a single decimal precision)?  The wiki chart would then use the data as-is.

I do agree that the value should be a number and not need to be parsed.

Comment 9

[James Sudduth]

I've made the first two changes Brent suggested and am awaiting review from Chris. I'm not sure how to incorporate the expect data, so I left the last column as is for now.

Comment 10

[James Sudduth]

Attachment: Changes to pending build queue wait time logging.

- Added a field header when the log file is created.
- The queue log time file will be updated every time any priority 1, 2, or 3 change files are moved from the pending to the processed queue. It should be always be unlocked and readable, except maybe when it's being written to (which should be very fast).
- Changed the last field, which was hours:minutes:seconds, to two fields, minutes and seconds. Minutes has single decimal precision.

Comment 11

[Chris Peyer]

Comment on attachment 442205 [details] [diff] [review]
Changes to pending build queue wait time logging.

looks good.  only minor thing is to split some of the longer lines into two lines.

Comment 12

[Chris Peyer]

One more thing: the script should copy the log file after each update (or store it) in e/AVMTeam/buildbot/master-tamarin-redux/public_html/analytics so that the file is http accessible.

Comment 13

[James Sudduth]

Attachment: Copy queue times log to where it's available via http

Shortened some long lines, adding copy to a folder accessible via http.

Comment 14

[Trevor Baker]

Comment on attachment 442479 [details] [diff] [review]
Copy queue times log to where it's available via http

+    shutil.copy(QUEUELOGTIME, MASTER_ROOT+'/public_html/analytics')

Shouldn't that be QUEUETIMELOG?

Also recommend queuetimes.log be named queuetimes.csv for clarity

Comment 15

[James Sudduth]

Attachment: Update to 442479

Added a boolean to config files so queue time logging is not done for the asc, perf and deep cycles. Corrected QUEUELOGTIME to QUEUETIMELOG. Changed log file name to use "csv" extension.

Comment 16

[James Sudduth]

Attachment: Removed unwanted readme.txt changes from patch file.

Comment 17

[Chris Peyer]

pushed to qe repo: http://asteam/hg/qe/rev/e2747142c600
and updated the in the master/scripts dir on playercore

Comment 18

[Trevor Baker]

+                fields_msg = "change-file,priority,branch,creation time,processed time,minutes in queue,\
+                                seconds in queue"

Since quoted, this space indenting results in 32 spaces in the column listing row.

Comment 19

[Trevor Baker]

I don't think the priority column is right.  I'm seeing sandbox builds listed as 3 and redux listed as 2, when I think it is actually the opposite.  Please confirm.

Comment 20

[James Sudduth]

It's a bit misleading because the numbers used for the change file extensions don't actually determine how watcher_trigger.py prioritizes its runs. The way they're parsed out in watcher_trigger.py lines 205-227, the sandbox builds get higher prioritization by the order of the if and elif statements, with sandbox being run before redux if a sandbox change file is present.

Comment 21

[James Sudduth]

Attachment: Remove line continuation on line 170 which added extra spaces before the last field of the csv file

Comment 22

[James Sudduth]

Neglected to close this after fixing the line continuation problem.