742937 - use separate tokens for results parsing, not just one giant regex

Status: RESOLVED FIXED

(Testing :: Talos, defect)

Description

[Jeff Hammel]

Currently, "Unrecognized output format" is a very ambiguous error:

http://hg.mozilla.org/build/talos/file/a9f14a82860e/talos/ttest.py#l384

This literally means "None of our regexes matched".  But why they
didn't match could mean one of many things:

- pageloader isn't loaded
- buffers weren't flushed or other IO error
- some pageloader internal error
- the final timestamp didn't get written properly (or similar)
- some other error

Instead, we should parse for these delimeter pairs individually so
that we can know exactly what the problem is:

http://hg.mozilla.org/build/talos/file/a9f14a82860e/talos/ttest.py#l74

Then we should raise a import informative error.

Comment 1

[Jeff Hammel]

AnalyzeThis uses tokens for splicing input:

http://k0s.org/mozilla/hg/AnalyzeThis/file/f2b4b13ffab1/analyzethis/utils.py

I'd prefer to use something like this

Comment 2

[Jeff Hammel]

I will also move the browser log parsing to results.py. There is no reason the already monolithic ttest.py file should do this

Comment 3

[Jeff Hammel]

Attachment: WIP

This actually doesn't do any of the error handling better at all; it just moves the logic out of ttest.py to results.py and adds some tests now that there is an API that is actually testable

Comment 4

[Jeff Hammel]

effectively blocks https://bugzilla.mozilla.org/show_bug.cgi?id=687116

Comment 5

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

Comment on attachment 612740 [details] [diff] [review]
WIP

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

overall this looks good.  Mostly a simple restructuring, but it really opens the gates for better code!

::: talos/ttest.py
@@ +74,1 @@
>      RESULTS_RESPONSIVENESS_REGEX = re.compile('MOZ_EVENT_TRACE\ssample\s\d*?\s(\d*?)$', re.DOTALL|re.MULTILINE)

what about the responsiveness regex?

Comment 6

[Jeff Hammel]

(In reply to Joel Maher (:jmaher) from comment #5)
> Comment on attachment 612740 [details] [diff] [review]
> WIP
> 
> Review of attachment 612740 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> overall this looks good.  Mostly a simple restructuring, but it really opens
> the gates for better code!

Thanks.  I actually meant to put for feedback and not review as I don't intend on landing until I fix the actual bug, but thanks for looking at it.

> ::: talos/ttest.py
> @@ +74,1 @@
> >      RESULTS_RESPONSIVENESS_REGEX = re.compile('MOZ_EVENT_TRACE\ssample\s\d*?\s(\d*?)$', re.DOTALL|re.MULTILINE)
> 
> what about the responsiveness regex?

I'm not sure what to do here. this regex is used in a different place and in a different way than the previous regexes. I thought about moving it to results.py and just having it called here, but i'm not sure its a real advantage.  What do you think?

Comment 7

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

ideally all stdout parsing should take place in the same area.  Especially stuff that we end up reporting.  Since we do report the responsiveness stuff and it is part of the stdout, I would like to get it in the same area.

The other hitch here is the counters.  RSS is collected from stdout now, so we need to resolve that as well.

Comment 8

[Jeff Hammel]

Okay, I'll do that fore responsiveness.  For counters, we should probably really rethink them a bit.  They are, across the board, currently a bit magic.

Comment 9

[Jeff Hammel]

So there is a current strangeness with responsiveness:  we parse it for each cycle, but we actually only use the last one:

http://hg.mozilla.org/build/talos/file/a9f14a82860e/talos/ttest.py#l412
http://hg.mozilla.org/build/talos/file/a9f14a82860e/talos/ttest.py#l423

I'm guessing something is wrong here and don't know A. what we want to do and B. whether we want to tie this to this bug

Comment 10

[Jeff Hammel]

(In reply to Jeff Hammel [:jhammel] from comment #9)
> So there is a current strangeness with responsiveness:  we parse it for each
> cycle, but we actually only use the last one:
> 
> http://hg.mozilla.org/build/talos/file/a9f14a82860e/talos/ttest.py#l412
> http://hg.mozilla.org/build/talos/file/a9f14a82860e/talos/ttest.py#l423
> 
> I'm guessing something is wrong here and don't know A. what we want to do
> and B. whether we want to tie this to this bug

I'm going to work under the assumption that we want to extend versus overwrite the results.  Lemme know if I'm wrong here

Comment 11

[Jeff Hammel]

Attachment: suggested fix

This gives better failure messages and has tests for parsing.  In this I just extend all responsiveness finds as per comments.  I don't know if this is what we want to do but I'm guessing what we do currently is wrong (the solutions are equivalent to the production case of having a single browser cycle).

Comment 12

[Jeff Hammel]

Attachment: exactly the same as the previous, just updated a docstring

Comment 13

[Mozilla RelEng Bot]

Try run for d2f7dc4482aa is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=d2f7dc4482aa
Results (out of 76 total builds):
    success: 7
    warnings: 2
    failure: 67
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-d2f7dc4482aa

Comment 14

[Jeff Hammel]

Comment on attachment 612995 [details] [diff] [review]
exactly the same as the previous, just updated a docstring

Beh forgot a colon.  Will put up a new patch shortly

Comment 15

[Jeff Hammel]

Attachment: final patch, i hope

Comment 16

[Jeff Hammel]

pushed to try, https://tbpl.mozilla.org/?tree=Try&rev=ac954657a3d9, but happened to coincide with mad infrastructure failures.  I tried restarting jobs but its pretty hard to say what is/isn't broken here, so I'll repush after this set of results come in. FWIW, none of the failures seemed related to the patch

Comment 17

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

Comment on attachment 613327 [details] [diff] [review]
final patch, i hope

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

a lot of code to review here, but this is looking really good.  I am unclear on the PageLoaderResults class in results.py, maybe that is something for raw results?

Comment 18

[Jeff Hammel]

pushed to try again: https://tbpl.mozilla.org/?tree=Try&rev=abd6b0240375

Its green except ts on android, which fails because the browser log isn't appropriately removed:

OISE: __startTimestamp1332535908581__endTimestamp
NOISE: __start_report2511__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1332535925633 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1332535923753" line: 0}]
NOISE: __startTimestamp1332535926322__endTimestamp
NOISE: __start_report2574__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1332535975149 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1332535973199" line: 0}]
NOISE: __startTimestamp1332535975817__endTimestamp
NOISE: __start_report2471__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1332535994108 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1332535992223" line: 0}]
NOISE: __startTimestamp1332535994760__endTimestamp
NOISE: __start_report2626__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1332536013254 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1332536011205" line: 0}]
NOISE: __startTimestamp1332536013877__endTimestamp
NOISE: __start_report3270__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1332536033143 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1332536030440" line: 0}]
NOISE: __startTimestamp1332536033760__endTimestamp
NOISE: __start_report2728__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1332536051836 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1332536049703" line: 0}]
NOISE: __startTimestamp1332536052488__endTimestamp
NOISE: __start_report2333__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1332536071575 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1332536069801" line: 0}]
NOISE: __startTimestamp1332536072184__endTimestamp
NOISE: __start_report2677__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1332536122896 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1332536120792" line: 0}]
NOISE: __startTimestamp1332536123523__endTimestamp
NOISE: __metrics	Screen width/height:1280/800
NOISE: 	colorDepth:16
NOISE: 	Browser inner width/height: 1280/696
NOISE: __metrics__start_report3140__end_report
NOISE: 
NOISE: Could not read chrome manifest 'file:///data/data/org.mozilla.fennec/chrome.manifest'.
NOISE: zerdatime 1334088311122 - browser chrome startup finished.
NOISE: OpenGL LayerManager Initialized Succesfully.
NOISE: Version: OpenGL ES 2.0
NOISE: Vendor: NVIDIA Corporation
NOISE: Renderer: NVIDIA Tegra
NOISE: FBO Texture Target: TEXTURE_2D
NOISE: [JavaScript Warning: "Use of enablePrivilege is deprecated.  Please use code that runs with the system principal (e.g. an extension) instead." {file: "http://10.251.27.101:15707/startup_test/startup_test.html?begin=1334088308584" line: 0}]
NOISE: __startTimestamp1334088311778__endTimestamp
NOISE: __startBeforeLaunchTimestamp1334088475258__endBeforeLaunchTimestamp
NOISE: __startAfterTerminationTimestamp1334088481479__endAfterTerminationTimestamp
getting files in '/mnt/sdcard/tests/profile/minidumps/'
Failed ts: 
		Stopped Tue, 10 Apr 2012 13:08:05
FAIL: Busted: ts
FAIL: Multiple matches for __start_report,__end_report [browser_output.txt]
Traceback (most recent call last):
  File "/home/jhammel/talos/bin/talos", line 8, in <module>
    load_entry_point('talos==0.0', 'console_scripts', 'talos')()
  File "/home/jhammel/talos/talos/run_tests.py", line 675, in main
    test_file(arg, options, parser.parsed)
  File "/home/jhammel/talos/talos/run_tests.py", line 616, in test_file
    raise e
talos.utils.talosError: 'Multiple matches for __start_report,__end_report [browser_output.txt]'

This gets removed here, http://hg.mozilla.org/build/talos/file/4343f5e91fae/talos/ttest.py#l262 , but since we copy over the file from the android device this does not suffice.  

We'll need a bug to remove this file on the device before we can re-test this.

Comment 19

[Mozilla RelEng Bot]

Try run for abd6b0240375 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=abd6b0240375
Results (out of 75 total builds):
    success: 73
    failure: 2
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-abd6b0240375

Comment 20

[Jeff Hammel]

Attachment: unbitrot

carrying jmaher's r+ forward

Comment 21

[Mozilla RelEng Bot]

Try run for 00268ef06c83 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=00268ef06c83
Results (out of 77 total builds):
    success: 76
    failure: 1
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-00268ef06c83

Comment 22

[Jeff Hammel]

looks pretty good, pushing

Comment 23

[Jeff Hammel]

pushed: https://bug742937.bugzilla.mozilla.org/attachment.cgi?id=615368