693645 - output firstTimestamp in the ts logs

Status: RESOLVED FIXED

(Testing :: Talos, defect)

Description

[Joel Maher ( :jmaher ) (UTC -8)]

it would be really good to know the total runtime a talos tests takes.  This is important as tests like ts and tshutdown can have different bits of code running in each part.  

In order to not change a lot, I am adding a __startFirstTimestamp after the __startSecondTimestamp.  This will be a bit confusing, but in the scenario of ts, here is what we would see:

1) __startReport314__endReport         
2) __startTimestamp123456789__endTimestamp
3) __startSecondTimestamp123456789__endSecondTimestamp
0) __startFirstTimestamp123456789__endSecondTimestamp

note that 0 is at the end of this list (for compatibility reasons).  If you calculate 3-0, you will get the total runtime.

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: output a firstTimestamp in talos to measure truntime (1.0)

need to test in staging before asking releng to deploy.

Comment 2

[Joel Maher ( :jmaher ) (UTC -8)]

all green in staging, please review so we can get the ball rolling :)

Comment 3

[William Lachance (:wlach)]

Comment on attachment 566243 [details] [diff] [review]
output a firstTimestamp in talos to measure truntime (1.0)

As discussed on irc, the concept is fine, but let's give these variables more descriptive names (both in the code and in our output) and put them in chronological order:

startFirstTimestamp -> beforeLaunchTimestamp
startSecondTimestamp -> afterTerminationTimestamp

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: output a firstTimestamp in talos to measure truntime (2.0)

looks good locally, running on talos staging.

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: output a firstTimestamp in talos to measure truntime (2.1)

forgot a couple updates for the tp regex.

Comment 6

[William Lachance (:wlach)]

Comment on attachment 566847 [details] [diff] [review]
output a firstTimestamp in talos to measure truntime (2.1)

As I said above I'd prefer if the internal variable names/functions (getFirstTime, etc.) were renamed to be more descriptive as well, but I'd say this can go in as is if it works in the testing environment. We can always clean that up later as part of another patch to bcontroller.py.

Comment 7

[William Lachance (:wlach)]

Comment on attachment 566847 [details] [diff] [review]
output a firstTimestamp in talos to measure truntime (2.1)

Review of attachment 566847 [details] [diff] [review]:
-----------------------------------------------------------------

As I said above I'd prefer if the internal variable names/functions (getFirstTime, etc.) were renamed to be more descriptive as well, but I'd say this can go in as is if it works in the testing environment. We can always clean that up later as part of another patch to bcontroller.py.

Comment 8

[Joel Maher ( :jmaher ) (UTC -8)]

http://hg.mozilla.org/build/talos/rev/9d66b5d45d0a

Comment 9

[Dietrich Ayala (:dietrich)]

Thanks everyone for jumping in to help make this test better so quickly.

Comment 10

[Joel Maher ( :jmaher ) (UTC -8)]

we still need to get this rolled out in production.  I filed a bug 694579 for deploying talos