If you think a bug might affect users in the 57 release, please set the correct tracking and status flags for Release Management.

testCheck2 runs for too long

RESOLVED WONTFIX

Status

Testing
Talos
RESOLVED WONTFIX
3 years ago
2 years ago

People

(Reporter: gbrown, Assigned: gbrown)

Tracking

Trunk
x86_64
Linux
Points:
---

Firefox Tracking Flags

(firefox40 affected)

Details

Attachments

(1 attachment)

(Assignee)

Description

3 years ago
Robocop-based Talos test testCheck2 takes a little over 30 minutes to run currently. Each run consists of 5 Talos iterations.

For one iteration, the Java code runs for about 170 seconds, which breaks down as:
 -  20 seconds loading the test page
 -  25 seconds scrolling, zooming and measuring checkerboarding
 - 120 seconds waiting for the browser to shutdown
 -   5 seconds other
(Assignee)

Comment 1

3 years ago
The 120 second wait for shutdown avoids a frequent shutdown crash which is associated with robocop.

I am trying to reduce or eliminate it.
(Assignee)

Comment 2

3 years ago
Another approach which interests me is to have the Java code run the checkerboarding test 5 times and reduce the Talos iterations to 1, eliminating the overhead of preparing the device, starting and shutting down the browser, etc.
right there we will save 8 minutes in not shutting down 4 addtional times, also saving 4 startup costs and other random non in browser overhead should get us closer to 10 minutes of savings.
(Assignee)

Comment 4

3 years ago
Oh no! Here's another way of looking at the problem...

Robocop tests (including testCheck2) send Robocop:Quit to http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/roboextender/bootstrap.js#46, then wait for the browser to shutdown for up to 2 minutes. In mochitest, on pandaboards, this normally takes less than 2 seconds. In talos, it looks like there is no roboextender, no one listening to Robocop:Quit, and so the test just waits for 2 minutes (for each of 5 iterations, wasting 10 minutes in total per testCheck2 run).
ok, we can add roboextender, I think we removed that a while back as everything ran fine without it.
(Assignee)

Comment 6

3 years ago
Created attachment 8586399 [details] [diff] [review]
wip

In https://treeherder.mozilla.org/#/jobs?repo=try&revision=42a3e74d502a, I see my debug message "ZZZ including roboextender for test tcheck2" but the test still acts like roboextender is not installed. Any ideas?
Attachment #8586399 - Flags: feedback?(jmaher)
Comment on attachment 8586399 [details] [diff] [review]
wip

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

this looks like the right stuff.  Can you look at the profile on the device to ensure we really copy the extension there?  Also I noticed that the testing/mochitest/roboextender/bootstrap.js is slightly different than what you have modified here- should they end up identical?

could you show the .yml file that is generated?
Attachment #8586399 - Flags: feedback?(jmaher) → feedback+
(Assignee)

Comment 8

3 years ago
If I run locally, it looks like everything is where it ought to be:

$ adb shell cat /mnt/sdcard/tests/profile/extensions.json
{"schemaVersion":16,"addons":[{"id":"roboextender@mozilla.org","syncGUID":"Yw1c4I5Ukr_l","location":"app-profile","version":"1.0","type":"extension","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Robocop Extender","description":null,"creator":"Joel Maher","homepageURL":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"descriptor":"/mnt/sdcard/tests/profile/extensions/roboextender@mozilla.org","installDate":1427900901000,"updateDate":1427900901000,"applyBackgroundUpdates":1,"bootstrap":true,"size":3085,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":false,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":"10.0","maxVersion":"*"}],"targetPlatforms":[],"multiprocessCompatible":false}]}

$ adb shell ls -l /mnt/sdcard/tests/profile/extensions
drwxrwxr-x root     sdcard_rw          2015-04-01 09:08 roboextender@mozilla.org

$ adb shell ls -l /mnt/sdcard/tests/profile/extensions/robo*
-rw-rw-r-- root     sdcard_rw     2367 2015-04-01 09:08 bootstrap.js
-rw-rw-r-- root     sdcard_rw      718 2015-04-01 09:08 install.rdf

$ cat local.yml
apk_path: /home/gbrown/objdirs/droid/dist/fennec-40.0a1.en-US.android-arm.apk
basetest:
  cleanup: null
  cycles: 1
  e10s: false
  linux_counters: []
  mac_counters: []
  mainthread: false
  profile_path: ${talos}/mobile_profile
  remote_counters: []
  resolution: 1
  responsiveness: false
  rss: false
  setup: null
  shutdown: false
  sps_profile: false
  sps_profile_entries: 100000
  sps_profile_interval: 1
  test_name_extension: ''
  timeout: 3600
  tpchrome: true
  tpcycles: 3
  tpdelay: 1000
  tpdisable_e10s: false
  tploadnocache: false
  tpmozafterpaint: false
  tpnoisy: true
  tppagecycles: 1
  tprender: false
  tpscrolltest: false
  w7_counters: []
  win_counters: []
  xperf_counters: []
bcontroller_config: ${talos}/bcontroller.yml
branch_name: ''
browser_log: browser_output.txt
browser_path: org.mozilla.fennec
browser_wait: 60
buildid: testbuildid
develop: false
deviceip: 192.168.0.86
deviceport: 20701
deviceroot: /mnt/sdcard/tests
dirs: {}
env:
  MOZ_CRASHREPORTER_SHUTDOWN: '1'
  NO_EM_RESTART: '1'
error_filename: /home/gbrown/Downloads/talos_zip/copy/browser_failures.txt
extensions:
- ${talos}/mobile_extensions/roboextender@mozilla.org
extra_args: ''
fennecIDs: /home/gbrown/objdirs/droid/dist/fennec_ids.txt
filters:
- - ignore_max
  - []
- - median
  - []
init_url: http://talos-remote.pvt.build.mozilla.org/getInfo.html
preferences:
  app.update.badge: false
  app.update.enabled: false
  browser.EULA.override: true
  browser.cache.disk.smart_size.enabled: false
  browser.cache.disk.smart_size.first_run: false
  browser.chrome.dynamictoolbar: false
  browser.contentHandlers.types.0.uri: http://127.0.0.1/rss?url=%s
  browser.contentHandlers.types.1.uri: http://127.0.0.1/rss?url=%s
  browser.contentHandlers.types.2.uri: http://127.0.0.1/rss?url=%s
  browser.contentHandlers.types.3.uri: http://127.0.0.1/rss?url=%s
  browser.contentHandlers.types.4.uri: http://127.0.0.1/rss?url=%s
  browser.contentHandlers.types.5.uri: http://127.0.0.1/rss?url=%s
  browser.devedition.theme.enabled: false
  browser.devedition.theme.showCustomizeButton: false
  browser.displayedE10SPrompt: 9999
  browser.displayedE10SPrompt.1: 9999
  browser.displayedE10SPrompt.2: 9999
  browser.displayedE10SPrompt.3: 9999
  browser.displayedE10SPrompt.4: 9999
  browser.displayedE10SPrompt.5: 9999
  browser.dom.window.dump.enabled: true
  browser.link.open_newwindow: 2
  browser.newtabpage.directory.ping: ''
  browser.newtabpage.directory.source: ${webserver}/directoryLinks.json
  browser.newtabpage.introShown: true
  browser.safebrowsing.enabled: false
  browser.safebrowsing.gethashURL: http://127.0.0.1/safebrowsing-dummy/gethash
  browser.safebrowsing.keyURL: http://127.0.0.1/safebrowsing-dummy/newkey
  browser.safebrowsing.malware.enabled: false
  browser.safebrowsing.updateURL: http://127.0.0.1/safebrowsing-dummy/update
  browser.search.countryCode: US
  browser.search.isUS: true
  browser.selfsupport.url: http://127.0.0.1/selfsupport-dummy/
  browser.shell.checkDefaultBrowser: false
  browser.snippets.enabled: false
  browser.snippets.syncPromo.enabled: false
  browser.tabs.remote.autostart: false
  browser.tabs.remote.autostart.1: false
  browser.tabs.remote.autostart.2: false
  browser.warnOnQuit: false
  browser.webapps.checkForUpdates: 0
  datareporting.healthreport.about.reportUrl: http://127.0.0.1/abouthealthreport/
  datareporting.healthreport.documentServerURI: http://127.0.0.1/healthreport/
  datareporting.policy.dataSubmissionPolicyBypassNotification: true
  devtools.chrome.enabled: false
  devtools.debugger.remote-enabled: false
  devtools.theme: light
  devtools.timeline.enabled: false
  devtools.webide.widget.enabled: false
  devtools.webide.widget.inNavbarByDefault: false
  dom.allow_scripts_to_close_windows: true
  dom.disable_open_during_load: false
  dom.disable_window_flip: true
  dom.disable_window_move_resize: true
  dom.max_script_run_time: 0
  dom.send_after_paint_to_content: true
  experiments.manifest.uri: https://127.0.0.1/experiments-dummy/manifest
  extensions.autoDisableScopes: 10
  extensions.blocklist.enabled: false
  extensions.blocklist.url: http://127.0.0.1/extensions-dummy/blocklistURL
  extensions.checkCompatibility: false
  extensions.enabledScopes: 5
  extensions.getAddons.get.url: http://127.0.0.1/extensions-dummy/repositoryGetURL
  extensions.getAddons.getWithPerformance.url: http://127.0.0.1/extensions-dummy/repositoryGetWithPerformanceURL
  extensions.getAddons.maxResults: 0
  extensions.getAddons.search.browseURL: http://127.0.0.1/extensions-dummy/repositoryBrowseURL
  extensions.getAddons.search.url: http://127.0.0.1/extensions-dummy/repositorySearchURL
  extensions.hotfix.url: http://127.0.0.1/extensions-dummy/hotfixURL
  extensions.update.background.url: http://127.0.0.1/extensions-dummy/updateBackgroundURL
  extensions.update.enabled: false
  extensions.update.notifyUser: false
  extensions.update.url: http://127.0.0.1/extensions-dummy/updateURL
  extensions.webservice.discoverURL: http://127.0.0.1/extensions-dummy/discoveryURL
  general.useragent.updates.enabled: false
  hangmonitor.timeout: 0
  identity.fxaccounts.auth.uri: https://127.0.0.1/fxa-dummy/
  identity.fxaccounts.migrateToDevEdition: false
  media.capturestream_hints.enabled: true
  media.gmp-manager.url: http://127.0.0.1/gmpmanager-dummy/update.xml
  media.navigator.enabled: true
  media.navigator.permission.disabled: true
  media.peerconnection.enabled: true
  network.http.speculative-parallel-limit: 0
  network.manage-offline-status: false
  plugins.update.url: http://127.0.0.1/plugins-dummy/updateCheckURL
  security.enable_java: false
  security.fileuri.strict_origin_policy: false
  security.turn_off_all_security_so_that_viruses_can_take_over_this_computer: true
  talos.logfile: /mnt/sdcard/tests/browser_output.txt
  toolkit.telemetry.notifiedOptOut: 999
  toolkit.telemetry.prompted: 999
  toolkit.telemetry.server: https://127.0.0.1/telemetry-dummy/
process: org.mozilla.fennec
remote: true
robocopTestName: org.mozilla.roboexample.test
robocopTestPackage: org.mozilla.gecko
test_timeout: 3600
tests:
- cycles: 5
  fennecIDs: true
  name: tcheck2
  timeout: 300
  url: am instrument -w -e deviceroot %s -e class org.mozilla.gecko.tests.testCheck2
    org.mozilla.roboexample.test/org.mozilla.gecko.FennecInstrumentationTestRunner
title: mobile
webserver: talos-remote.pvt.build.mozilla.org
yeah, everything looks on the level.  This makes me wonder if there is a preference set or some other setting which is causing the extension not to work?  Maybe roboextender is problematic due to not being run for a while or there is something specific to tcheck2 which is causing issues.  I did look through the testcheck2 code and didn't see anything that looked out of the ordinary.  It is a pixeltest and there is no sign of us overloading teardown in the test or pixeltest such that it removes the quit.
(Assignee)

Comment 10

3 years ago
(In reply to Joel Maher (:jmaher) from comment #7)
>  Also I noticed that the
> testing/mochitest/roboextender/bootstrap.js is slightly different than what
> you have modified here- should they end up identical?

I tried another run with an identical bootstrap.js, and also added chrome.manifest for good measure but saw no change in behavior -- http://ftp.mozilla.org/pub/mozilla.org/mobile/try-builds/gbrown@mozilla.com-42a3e74d502a/try-android-api-11/try_panda_android_test-remote-trobocheck2-bm102-tests1-panda-build125.txt.gz.
(Assignee)

Comment 11

3 years ago
Now I have verified on try that roboextender's startup() is called and executes:

  Services.obs.addObserver(function observe(aSubject, aTopic, aData) { ... }, "Robocop:Quit", false);

and BaseTest.tearDown() is called and executes:

  GeckoAppShell.sendEventToGecko(GeckoEvent.createBroadcastEvent("Robocop:Quit", null));

but the roboextender observe function is never called. What!?
(Assignee)

Comment 12

3 years ago
MotionEventReplayer.replayEvents() somehow interferes with subsequent event processing. "Robocop:Quit" is added to the nsAppShell event queue, but not processed. If replayEvents() is not called, Robocop:Quit is processed and the browser shuts down cleanly and quickly.
(Assignee)

Comment 13

3 years ago
I monitored, via DEBUG_ANDROID_EVENTS, nsAppShell events and noticed a Gesture:DoubleTap shortly before the event queue stopped being processed. I also noticed these messages just after the double tap:

13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: stackwalker.cc:125: INFO: Couldn't load symbols for: libnativehelper.so|
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x0
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x0
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x0
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x0
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x0
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x0
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x39c2a1
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x0
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x12
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x10
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x13670a0
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x658
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x5b9
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x1367140
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x1365918
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: stackwalker.cc:125: INFO: Couldn't load symbols for: libc.so|
13:05:47     INFO -  04-09 13:02:26.953 E/Profiler( 2796): 2015-04-09 13:02:26: basic_code_modules.cc:88: INFO: No module at 0x1363a08

If I hack nsAppShell to drop all Gesture:DoubleTap, the problems go away: no Profiler messages, the event queue is processed, and Robocop:Quit is processed and causes rapid clean shutdown. Also, the regression seen in bug 1097318 from http://hg.mozilla.org/integration/fx-team/rev/4f72c81d5441 is reversed.

Speculative theory: The change in 4f72c81d5441 modified the content window dimensions such that some of the replayed events now stray into chrome, or tap/double-tap on content elements that pop up something which holds focus and prevents event processing for the remainder of the test.

Unfortunately, I cannot reproduce the behavior on any of my devices, and I cannot see what's happening on the pandaboard.

If I dump the first MotionEvent seen by JavaPanZoomController's onDoubleTap, I get { action=ACTION_DOWN, id[0]=0, x[0]=708.0, y[0]=287.0, toolType[0]=TOOL_TYPE_UNKNOWN, buttonState=0, metaState=0, flags=0x0, edgeFlags=0x0, pointerCount=1, historySize=0, eventTime=1460247, downTime=1460247, deviceId=0, source=0x1002 }, but I don't see those coordinates in http://hg.mozilla.org/mozilla-central/file/dd32e3ff3717/mobile/android/base/tests/assets/testcheck2-motionevents.

:kats -- Got any suggestions for how to proceed?
Flags: needinfo?(bugmail.mozilla)
Hm interesting. If the double tap message is in nsAppShell that should mean that it's not hitting chrome area but must be hitting content. It might be worth adding logging to the Gesture:DoubleTap code in browser.js to see what happens when it runs (or bisect it to see which part is causing the problem). I'm not sure how any of that code would be able to cause any focus changes, or cause loading of libnativehelper.so.

As for the coordinates, the MotionEventReplayer tries to scale the coordinates [1] from the device the capture was taken on to the device it's being played back on, so that's probably why you're not seeing the exact values in the file.

[1] http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/MotionEventReplayer.java?rev=2878bf6cbc1f#82
Flags: needinfo?(bugmail.mozilla)
Also is it possible to modify the scripts to take a screenshot when it gets stuck on the pandaboard?
(Assignee)

Comment 16

2 years ago
kats -- Thanks for your comments. I tried following up but got bogged down, then distracted. :)

jmaher is making good progress on getting this test running on autophone. It may be best to just follow-up on the autophone version, if that has similar problems (but fingers crossed...)
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.