1428790 - Intermittent command timed out: 7200 seconds elapsed running ['/tools/buildbot/bin/python', 'scripts/scripts/talos_script.py', '--suite', 'h2-e10s', '--add-option', '--webServer,localhost', '--branch-name', 'Mozilla-Inbound-Non-PGO', '--cfg'

Status: RESOLVED FIXED

(Testing :: Talos, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: aiakab [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=154685960&repo=mozilla-inbound

https://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-inbound-linux64/mozilla-inbound_ubuntu64_hw_test-h2-e10s-bm103-tests1-linux-build746.txt.gz

Comment 1

[Intermittent Failures Robot]

60 failures in 149 pushes (0.403 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 25
* mozilla-inbound: 24
* mozilla-central: 6
* mozilla-beta: 5

Platform breakdown:
* linux64: 57
* linux64-qr: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-11&endday=2018-01-11&tree=all

Comment 2

[Eliza Balazs [:ebalazs_]]

Since this bug was opened (in the last 3 days) there are 77 failures.
They occur mostly on Linux x64 and the rest of them on OS X 10.10, Windows 7, Windows10 64. The affected builds type are debug, opt, pgo.
Recent log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=154685960&lineNumber=8278
and a relevant part of it:

8278
command timed out: 7200 seconds elapsed running ['/tools/buildbot/bin/python', 'scripts/scripts/talos_script.py', '--suite', 'h2-e10s', '--add-option', '--webServer,localhost', '--branch-name', 'Mozilla-Inbound-Non-PGO', '--cfg', 'talos/linux_config.py', '--download-symbols', 'ondemand', '--use-talos-json', '--blob-upload-branch', 'Mozilla-Inbound-Non-PGO'], attempting to kill
8279
process killed by signal 9
8280
program finished with exit code -1
8281
elapsedTime=7200.009734
8282
========= master_lag: 0.13 =========
:rwood, can you please have a look at this?

Comment 3

[Kartikaya Gupta (email:[e-mail])]

The log seems to indicate that the h2 talos spends a lot of time copying profiles. Note the timestamps:

12:54:37     INFO -  Cloning profile located at /home/cltbld/.mozilla/profiles/simple
12:54:37     INFO -  => minidumps
12:54:37     INFO -  => bookmarkbackups
12:54:37     INFO -  => safebrowsing
12:54:37     INFO -  => OfflineCache
12:54:37     INFO -  => sessionstore-backups
12:54:37     INFO -  => crashes
12:54:37     INFO -  => crashes/events
12:54:37     INFO -  => browser-extension-data
12:54:37     INFO -  => browser-extension-data/[e-mail]
12:54:37     INFO -  => datareporting
12:54:37     INFO -  => datareporting/archived
12:54:37     INFO -  => datareporting/archived/2017-11
12:54:38     INFO -  => datareporting/archived/2017-10
12:54:38     INFO -  => datareporting/archived/2018-01
12:54:38     INFO -  => datareporting/archived/2017-09
12:54:38     INFO -  => datareporting/archived/2017-12
12:54:38     INFO -  => startupCache
12:54:38     INFO -  => gmp
12:54:38     INFO -  => gmp/Linux_x86_64-gcc3
12:54:38     INFO -  => storage
12:54:38     INFO -  => storage/permanent
12:54:38     INFO -  => storage/permanent/chrome
12:54:38     INFO -  => storage/permanent/chrome/idb
12:54:38     INFO -  => storage/permanent/chrome/idb/3561288849sdhlie.files
12:54:38     INFO -  => storage/permanent/chrome/idb/2918063365piupsah.files
12:54:38     INFO -  => storage/temporary
12:54:38     INFO -  => storage/default
12:54:38     INFO -  => storage/default/https+++ir.ebaystatic.com
12:54:38     INFO -  => storage/default/https+++ir.ebaystatic.com/idb
12:54:38     INFO -  => storage/default/https+++ir.ebaystatic.com/idb/12183338011.files
12:54:38     INFO -  => storage/default/https+++tpc.googlesyndication.com
12:54:38     INFO -  => storage/default/https+++tpc.googlesyndication.com/idb
12:54:38     INFO -  => storage/default/https+++tpc.googlesyndication.com/idb/12183338011.files
12:54:38     INFO -  => storage/default/https+++ad.doubleclick.net
12:54:38     INFO -  => storage/default/https+++ad.doubleclick.net/idb
12:54:38     INFO -  => storage/default/https+++ad.doubleclick.net/idb/12183338011.files
12:54:38     INFO -  => storage/default/https+++www.youtube.com
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache/morgue
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache/morgue/54
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache/morgue/56
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache/morgue/35
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache/morgue/84
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache/morgue/194
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache/morgue/22
12:54:38     INFO -  => storage/default/https+++www.youtube.com/cache/morgue/118
12:54:38     INFO -  => storage/default/https+++www.youtube.com/idb
12:54:38     INFO -  => storage/default/https+++www.youtube.com/idb/3211250388sbwdpsunsohintoatciif.files
12:54:38     INFO -  => storage/default/https+++images-na.ssl-images-amazon.com
12:54:38     INFO -  => storage/default/https+++images-na.ssl-images-amazon.com/idb
12:54:38     INFO -  => storage/default/https+++images-na.ssl-images-amazon.com/idb/12183338011.files
12:54:38     INFO -  => gmp-gmpopenh264
12:54:38     INFO -  => gmp-gmpopenh264/1.6
12:54:38     INFO -  => gmp-gmpopenh264/1.7.1
12:54:38     INFO -  => saved-telemetry-pings
12:54:39     INFO -  => cache2
12:54:39     INFO -  => cache2/entries
13:20:03     INFO -  => cache2/doomed
13:20:04     INFO -  => thumbnails


It looks like copying cache2/entries takes 20+ minutes, and this happens 4 times during a single run of h2. All the h2 seem to take close to 2 hours and will randomly go over 2 hours, resulting in this failure. This "simple" profile doesn't seem very simple, and might have gotten polluted somewhere along the way.

Comment 4

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

yeah, windows is slow by far- possibly we need to determine how to only unpack the profile once.  :rwood, could you look into this to see if we can realistically only unpack/copy the profile once?

Comment 5

[Robert Wood [:rwood]]

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #4)
> yeah, windows is slow by far- possibly we need to determine how to only
> unpack the profile once.  :rwood, could you look into this to see if we can
> realistically only unpack/copy the profile once?

Sure I'll have a look, thx

Comment 6

[Intermittent Failures Robot]

109 failures in 148 pushes (0.736 failures/push) were associated with this bug yesterday.    

** This test has failed more than 200 times in the last 30 days. It should be disabled until it can be fixed. ** 

Repository breakdown:
* autoland: 63
* mozilla-inbound: 39
* mozilla-central: 5
* try: 1
* mozilla-beta: 1

Platform breakdown:
* linux64: 107
* linux64-qr: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-12&endday=2018-01-12&tree=all

Comment 7

[Intermittent Failures Robot]

65 failures in 56 pushes (1.161 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 27
* mozilla-inbound: 21
* mozilla-central: 13
* mozilla-beta: 3
* try: 1

Platform breakdown:
* linux64: 58
* linux64-qr: 7

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-13&endday=2018-01-13&tree=all

Comment 8

[Intermittent Failures Robot]

318 failures in 788 pushes (0.404 failures/push) were associated with this bug in the last 7 days. 

This is the #2 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 166
* mozilla-inbound: 104
* mozilla-central: 36
* mozilla-beta: 10
* try: 2

Platform breakdown:
* linux64: 292
* linux64-qr: 17
* windows7-32: 3
* windows10-64: 3
* osx-10-10: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-08&endday=2018-01-14&tree=all

Comment 9

[Robert Wood [:rwood]]

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #4)
> yeah, windows is slow by far- possibly we need to determine how to only
> unpack the profile once.  :rwood, could you look into this to see if we can
> realistically only unpack/copy the profile once?

I spent some time looking into this. Problems with this approach (copying the profile once):

- we currently blow away the temporary folder used by talos which includes the profile; if we want to reuse the profile we'll need to keep the temporary folder around
- when running tp6 we have to install a mitmproxy CA certificate into the profile and set up a Firefox proxy; right now we are blowing away the profile so we don't have to remove those. However if we want to reuse the same profile we'll need to write code to remove the CA certificate and also remove the proxy
- we set browser prefs for the tppageloader options; if we aren't blowing away the profile then we'll have to make sure we remove/reset any of those browser prefs after the test run
- I'm a bit concerned about running tests using the same profile and the impact that may have on tests further down the chain

IMO I don't think just copying the profile once is the way to go here. Problem is I don't have another solution in mind ATM.

Comment 10

[Kartikaya Gupta (email:[e-mail])]

Can we use a slimmer profile then? It seems like most of the time is spent copying cache entries in the profile, if we can reduce the cache size in the canned profile it will likely help quite a bit.

Comment 11

[Robert Wood [:rwood]]

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #10)
> Can we use a slimmer profile then? It seems like most of the time is spent
> copying cache entries in the profile, if we can reduce the cache size in the
> canned profile it will likely help quite a bit.

The profile is heavy/large on purpose to test using a heavy user profile, so that would default the purpose really IMO. We may need to just disable this on Windows as it's fine on the other platforms.

:tarek, what do you think? I think we need to disable this on Windows, or as Kartikaya suggests use a reduced heavy profile (however is there a point to the test then?). Thanks!

Comment 12

[Kartikaya Gupta (email:[e-mail])]

This is already disabled on Windows. It's failing on linux64 mostly, now.

Comment 13

[Robert Wood [:rwood]]

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #12)
> This is already disabled on Windows. It's failing on linux64 mostly, now.

Ah right yes, I saw the 'h2' symbol on inbound Win 10 - turns out mochitest headless also uses the same 'h2' symbol

Comment 14

[Robert Wood [:rwood]]

Talos h1 (heavy 1) is still running on Windows but not h2

Comment 15

[Intermittent Failures Robot]

74 failures in 84 pushes (0.881 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 39
* mozilla-inbound: 22
* mozilla-central: 10
* try: 3

Platform breakdown:
* linux64: 68
* linux64-qr: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-15&endday=2018-01-15&tree=all

Comment 16

[Intermittent Failures Robot]

120 failures in 145 pushes (0.828 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 69
* mozilla-inbound: 33
* mozilla-central: 11
* mozilla-beta: 7

Platform breakdown:
* linux64: 115
* linux64-qr: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-16&endday=2018-01-16&tree=all

Comment 17

[Tarek Ziadé (:tarek)]

Yeah I think we could skip windows altogether since copying around files is notoriously slow there

Comment 18

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

we need to skip linux also

Comment 19

[Robert Wood [:rwood]]

Talos h1 has the same issue on Win10 (Bug 1428794). Alright I'm going to disable h1 and h2 on Windows and Linux, at least until a fix can be found...

Comment 21

[Robert Wood [:rwood]]

Attachment: Bug 1428790 - Disable talos heavy user profile tests on windows and linux;

Review commit: https://reviewboard.mozilla.org/r/213624/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/213624/

Comment 22

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

Comment on attachment 8943313 [details]
Bug 1428790 - Disable talos heavy user profile tests on windows and linux;

https://reviewboard.mozilla.org/r/213624/#review219342

ok!

Comment 23

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 8943313 [details]
Bug 1428790 - Disable talos heavy user profile tests on windows and linux;

https://reviewboard.mozilla.org/r/213624/#review219348

::: taskcluster/ci/test/talos.yml:216
(Diff revision 1)
>      try-name: h1
>      treeherder-symbol: tc-T(h1)
>      max-run-time: 5400
>      run-on-projects:
>          by-test-platform:
>              .*-qr/.*: ['mozilla-central', 'try']

You'll need to drop this -qr line as well. Same in h2. Otherwise platforms like linux64-qr will match both the .*-qr/.* line and linux.* and the python code will complain about it

Comment 24

[Robert Wood [:rwood]]

Comment on attachment 8943313 [details]
Bug 1428790 - Disable talos heavy user profile tests on windows and linux;

https://reviewboard.mozilla.org/r/213624/#review219348

Just discovered that on my try push, thanks!

Comment 25

[Robert Wood [:rwood]]

Comment on attachment 8943313 [details]
Bug 1428790 - Disable talos heavy user profile tests on windows and linux;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/213624/diff/1-2/

Comment 26

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/89cb08844b17
Disable talos heavy user profile tests on windows and linux; r=jmaher

Comment 27

[Tiberius Oros[:tiberius_oros]]

https://hg.mozilla.org/mozilla-central/rev/89cb08844b17

Comment 28

[Intermittent Failures Robot]

130 failures in 143 pushes (0.909 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 73
* mozilla-inbound: 49
* mozilla-central: 7
* mozilla-beta: 1

Platform breakdown:
* linux64: 127
* linux64-qr: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-17&endday=2018-01-17&tree=all

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-release/rev/a3c6c687eba1

Comment 30

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/472ecdbbe0ca (FIREFOX_58b_RELBRANCH)

Comment 32

[Intermittent Failures Robot]

375 failures in 657 pushes (0.571 failures/push) were associated with this bug in the last 7 days. 

This is the #4 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 217
* mozilla-inbound: 112
* mozilla-central: 32
* mozilla-beta: 8
* try: 6

Platform breakdown:
* linux64: 359
* linux64-qr: 16

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-15&endday=2018-01-21&tree=all

Comment 33

[Intermittent Failures Robot]

2 failures in 735 pushes (0.003 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-beta: 2

Platform breakdown:
* osx-10-10: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428790&startday=2018-01-29&endday=2018-02-04&tree=all