Closed Bug 1578733 Opened 5 years ago Closed 5 years ago

--cpu-test is recording cpu usage at the start of tests and not at the end

Categories

(Testing :: Raptor, defect, P2)

Product:
Testing
Component:
Raptor
Version:
Version 3
Type:
defect

Tracking

(firefox71 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla71
Tracking Flags:
Tracking Status
firefox71 --- fixed

People

(Reporter: sparky, Assigned: sparky)

Details

Attachments

(1 file, 1 obsolete file)

Bug 1578733 - Implement AndroidCpuProfiler for CPU usage measurements. r?#perftest
47 bytes, text/x-phabricator-request
Details | Review

CPU usage is being recorded before the test starts and this results in 0 CPU usage for MotoG5 (android 7) tests. See this set of tests for an example: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&tier=1%2C2%2C3&searchStr=power&revision=174361d152923aea2b24226a57cde3099509ed6a&selectedJob=264918873

[task 2019-09-04T11:17:09.322Z] 11:17:08     INFO -  adb launch_application: am start -W -n org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity -a android.intent.action.MAIN -d about:blank
[task 2019-09-04T11:17:09.322Z] 11:17:09     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell am start -W -n org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity -a android.intent.action.MAIN -d about:blank, timeout: None, root: False, timedout: None, exitcode: 0, output: Starting: Intent { act=android.intent.action.MAIN dat=about:blank cmp=org.mozilla.geckoview_example/.GeckoViewActivity }
[task 2019-09-04T11:17:09.322Z] 11:17:09     INFO -  Status: ok
[task 2019-09-04T11:27:47.741Z] 11:17:09     INFO -  Activity: org.mozilla.geckoview_example/.GeckoViewActivity
[task 2019-09-04T11:27:47.741Z] 11:17:09     INFO -  ThisTime: 356
[task 2019-09-04T11:27:47.741Z] 11:17:09     INFO -  TotalTime: 356
[task 2019-09-04T11:27:47.741Z] 11:17:09     INFO -  WaitTime: 375
[task 2019-09-04T11:27:47.741Z] 11:17:09     INFO -  Complete
[task 2019-09-04T11:27:47.741Z] 11:17:09     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell pidof org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: 6790
[task 2019-09-04T11:27:47.741Z] 11:17:09     INFO -  raptor-results-handler Info: RaptorResultsHandler.add_supporting_data received cpu data
[task 2019-09-04T11:27:47.741Z] 11:17:10     INFO -  raptor-control-server Info: received webext_status: raptor runner.js is loaded!
[task 2019-09-04T11:27:47.741Z] 11:17:10     INFO -  raptor-control-server Info: reading test settings from json/raptor-scn-power-idle-bg-geckoview.json
[task 2019-09-04T11:27:47.741Z] 11:17:10     INFO -  raptor-control-server Info: sent test settings to webext runner
[task 2019-09-04T11:27:47.741Z] 11:17:10     INFO -  raptor-control-server Info: received webext_status: * pausing 30 seconds to let browser settle... *
[task 2019-09-04T11:27:47.741Z] 11:17:40     INFO -  raptor-control-server Info: received request to foreground app
[task 2019-09-04T11:27:47.741Z] 11:17:40     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell am start --activity-single-top org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x20000000 pkg=org.mozilla.geckoview_example }
[task 2019-09-04T11:27:47.741Z] 11:17:40     INFO -  Warning: Activity not started, its current task has been brought to the front
[task 2019-09-04T11:27:47.741Z] 11:17:40     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell dumpsys deviceidle enable, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:27:47.741Z] 11:17:40     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell dumpsys window windows | grep mCurrentFocus, timeout: None, root: False, timedout: None, exitcode: 0, output:   mCurrentFocus=Window{f4da548 u0 org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity}
[task 2019-09-04T11:27:47.741Z] 11:17:40     INFO -  raptor-control-server Info: org.mozilla.geckoview_example was successfully foregrounded
[task 2019-09-04T11:27:47.741Z] 11:17:45     INFO -  raptor-control-server Info: received webext_status: running 1 pagecycles of about:blank
[task 2019-09-04T11:27:47.741Z] 11:17:45     INFO -  raptor-control-server Info: received request to background app
[task 2019-09-04T11:27:47.741Z] 11:17:45     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell dumpsys deviceidle whitelist +org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: Added: org.mozilla.geckoview_example
[task 2019-09-04T11:27:47.741Z] 11:17:46     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell input keyevent 3, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:27:47.741Z] 11:17:46     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell dumpsys window windows | grep mCurrentFocus, timeout: None, root: False, timedout: None, exitcode: 0, output:   mCurrentFocus=Window{6942c10 u0 com.google.android.apps.nexuslauncher/com.google.android.apps.nexuslauncher.NexusLauncherActivity}
[task 2019-09-04T11:27:47.741Z] 11:17:46     INFO -  raptor-control-server Info: org.mozilla.geckoview_example was successfully backgrounded
[task 2019-09-04T11:27:47.741Z] 11:17:46     INFO -  raptor-control-server Info: received webext_status: begin pagecycle 1
[task 2019-09-04T11:27:47.741Z] 11:17:47     INFO -  raptor-control-server Info: received webext_status: update tab: 0
[task 2019-09-04T11:27:47.741Z] 11:17:47     INFO -  raptor-control-server Info: received webext_status: started scenario test timer
[task 2019-09-04T11:27:47.741Z] 11:17:47     INFO -  raptor-control-server Info: received webext_status: test tab updated: 0
[task 2019-09-04T11:27:47.741Z] 11:27:47     INFO -  raptor-control-server Info: received webext_status: scenario test ended
[task 2019-09-04T11:27:47.741Z] 11:27:47     INFO -  raptor-control-server Info: received webext_status: results received
[task 2019-09-04T11:27:47.741Z] 11:27:47     INFO -  raptor-control-server Info: received request to foreground app
[task 2019-09-04T11:27:47.741Z] 11:27:47     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell am start --activity-single-top org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x20000000 pkg=org.mozilla.geckoview_example }
[task 2019-09-04T11:28:13.560Z] 11:27:47     INFO -  Warning: Activity not started, its current task has been brought to the front
[task 2019-09-04T11:28:13.560Z] 11:27:47     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell dumpsys deviceidle enable, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:28:13.560Z] 11:27:47     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell dumpsys window windows | grep mCurrentFocus, timeout: None, root: False, timedout: None, exitcode: 0, output:   mCurrentFocus=Window{f4da548 u0 org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity}
[task 2019-09-04T11:28:13.560Z] 11:27:47     INFO -  raptor-control-server Info: org.mozilla.geckoview_example was successfully foregrounded
[task 2019-09-04T11:28:13.560Z] 11:27:52     INFO -  raptor-control-server Info: received webext_results: {u'expected_browser_cycles': 1, u'subtest_unit': u'scenarioComplete', u'name': u'raptor-scn-power-idle-bg-geckoview', u'lower_is_better': True, u'measurements': {u'scenario': [1]}, u'browser_cycle': u'1', u'subtest_lower_is_better': True, u'cold': False, u'browser': u'Fennec 71.0a1 20190904094319', u'type': u'scenario', u'page': u'about:blank', u'unit': u'scenarioComplete', u'alert_threshold': 2}
[task 2019-09-04T11:28:13.560Z] 11:27:52     INFO -  raptor-control-server Info: Waiting in webext_shutdownBrowser
[task 2019-09-04T11:28:13.560Z] 11:27:52     INFO -  raptor-results-handler Info: received results in RaptorResultsHandler.add
[task 2019-09-04T11:28:13.560Z] 11:27:53     INFO -  raptor-results-handler Info: RaptorResultsHandler.add_supporting_data received memory data
[task 2019-09-04T11:28:13.561Z] 11:27:53     INFO -  raptor-control-server Info: received wait-continue:
[task 2019-09-04T11:28:13.561Z] 11:27:53     INFO -  raptor-control-server Info: received request to shutdown the browser
[task 2019-09-04T11:28:13.561Z] 11:27:53     INFO -  raptor-control-server Info: shutting down android app org.mozilla.geckoview_example
[task 2019-09-04T11:28:13.561Z] 11:27:53     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell am force-stop org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell settings put system screen_off_timeout 7200000, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell settings put system screen_brightness 0, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell dumpsys battery, timeout: None, root: False, timedout: None, exitcode: 0, output: Current Battery Service state:
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    AC powered: false
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    USB powered: false
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    Wireless powered: false
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    Max charging current: 0
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    Max charging voltage: 0
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    Charge counter: 654834
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    status: 3
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    health: 2
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    present: true
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    level: 31
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    scale: 100
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    voltage: 3658
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    temperature: 330
[task 2019-09-04T11:28:13.561Z] 11:27:54     INFO -    technology: Li-ion
[task 2019-09-04T11:28:13.561Z] 11:27:55     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell getprop ro.build.version.release, timeout: None, root: False, timedout: None, exitcode: 0, output: 8.0.0
[task 2019-09-04T11:28:13.561Z] 11:27:55     INFO -  raptor-power Info: power data for uid: u0a120, cpu: 1.21, wifi: 2.78e-05, screen: 2.66, proportional: 0.511
[task 2019-09-04T11:28:13.561Z] 11:27:55     INFO -  raptor-power Info: submitting power data via control server directly
[task 2019-09-04T11:28:13.561Z] 11:27:55     INFO -  raptor-results-handler Info: RaptorResultsHandler.add_supporting_data received power data
[task 2019-09-04T11:28:13.561Z] 11:27:55     INFO -  raptor-power Info: Approximate power test time 10.8333333333
[task 2019-09-04T11:28:13.561Z] 11:27:55     INFO -  raptor-results-handler Info: RaptorResultsHandler.add_supporting_data received power data
[task 2019-09-04T11:28:13.561Z] 11:27:55     INFO -  raptor-results-handler Info: RaptorResultsHandler.add_supporting_data received power data
[task 2019-09-04T11:28:13.561Z] 11:27:55     INFO -  raptor-power Info: generating power bugreport zip
[task 2019-09-04T11:28:14.597Z] 11:28:13     INFO -  adb command_output: adb -s 10.7.205.74:5555 wait-for-device bugreport /builds/task_1567595666/workspace/build/blobber_upload_dir, timeout: None, timedout: None, exitcode: 0, output: /data/user_de/0/com.android.shell/files/bugreports/bugreport-walleye-OPD1.170816.018-2019-09-04-04-27-55.zip: 1 file pulled. 6.3 MB/s (1503208 bytes in 0.226s)
[task 2019-09-04T11:28:14.597Z] 11:28:13     INFO -  raptor-main Info: removing reverse socket connections
[task 2019-09-04T11:28:14.597Z] 11:28:13     INFO -  adb command_output: adb -s 10.7.205.74:5555 wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  adb shell_bool: adb -s 10.7.205.74:5555 wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  adb shell_output: adb -s 10.7.205.74:5555 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  adb shell_bool: adb -s 10.7.205.74:5555 wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  adb command_output: adb -s 10.7.205.74:5555 wait-for-device pull /sdcard/raptor/profile/minidumps /tmp/tmpR3EU69/minidumps, timeout: None, timedout: None, exitcode: 0, output: /sdcard/raptor/profile/minidumps/: 0 files pulled.
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  raptor-main Info: removing webext /builds/task_1567595666/workspace/build/tests/raptor/raptor/../webext/raptor
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  raptor-results-handler Info: summarizing raptor test results
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  raptor-output Info: ignoring the first scenario value due to initial pageload noise
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  raptor-output Info: summarizing cpu data
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  raptor-output Info: summarizing memory data
[task 2019-09-04T11:28:14.597Z] 11:28:14     INFO -  raptor-output Info: summarizing power data
Attachment #9090505 - Attachment is obsolete: true

So from my investigation into this so far, the dumpsys cpuinfo command is not very good for our use case as it has no command line options (from what I can tell) and it's measurement window is extremely small which returns 0 %CPU usage very often. We should switch to using adb shell top instead. The -O %CPU option doesn't exist for Android 7, but it only orders the entries in top according to the %CPU column. Using something like top -n 1 will give us a list with the firefox browser app in it.

We should also see if we can try to add the -d <TIME> option to get an average of cpu usage over time - this would help measurements on both android versions and the "snapshot" would be more representative of what is being test.

EDIT: The -d option only applies to the delay between updates when viewing top without the -n 1. So it doesn't apply here.

This patch modifies how CPU usage is measured. First, it swaps out dumpsys cpuinfo in favor of top for android 7 devices. Next, a new class AndroidCpuProfiler is created for CPU polling since top only returns a snapshot and is not representative of what the browser has been doing (previously, we only measured CPU usage before the test started).

The CPU profiler/poller is started where the snapshot used to be generated and the perfherder data is now generated before the browser shuts down to prevent recording noise from the shutdown. The poller gathers a data point every 10 seconds, but this can be modified. It then produces perfherder-data for the average, minimum, and maximum CPU usage over the course of the test. The existing CPU tests have also been modified to accomodate these changes.

Pushed by gmierz2@outlook.com:
https://hg.mozilla.org/integration/autoland/rev/e388b6a82a5e
Implement AndroidCpuProfiler for CPU usage measurements. r=stephendonner

https://hg.mozilla.org/mozilla-central/rev/e388b6a82a5e

Status: NEW → RESOLVED
Closed: 5 years ago
status-firefox71: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla71
Assignee: nobody → gmierz2
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: