Perma fenix results.MissingResultsError: Browsertime cycle missing firstPaint measurement
Categories
(Testing :: Raptor, defect, P5)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=328528210&repo=fenix
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YyzednpMQouQC4jCuqEmUA/runs/0/artifacts/public/logs/live_backing.log
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - perftest-results-handler Info: parsing results from browsertime json
[task 2021-02-02T06:30:02.662Z] 06:29:29 ERROR - Traceback (most recent call last):
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - File "/builds/task_161224576203351/workspace/build/tests/raptor/raptor/raptor.py", line 212, in <module>
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - main()
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - File "/builds/task_161224576203351/workspace/build/tests/raptor/raptor/raptor.py", line 158, in main
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - File "/builds/task_161224576203351/workspace/build/tests/raptor/raptor/browsertime/android.py", line 235, in run_tests
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - return super(BrowsertimeAndroid, self).run_tests(tests, test_names)
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - File "/builds/task_161224576203351/workspace/build/tests/raptor/raptor/perftest.py", line 404, in run_tests
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - return self.process_results(tests, test_names)
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - File "/builds/task_161224576203351/workspace/build/tests/raptor/raptor/perftest.py", line 425, in process_results
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - res = self.results_handler.summarize_and_output(self.config, tests, test_names)
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - File "/builds/task_161224576203351/workspace/build/tests/raptor/raptor/results.py", line 743, in summarize_and_output
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - test.get("measure"),
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - File "/builds/task_161224576203351/workspace/build/tests/raptor/raptor/results.py", line 601, in parse_browsertime_json
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - raptor
[task 2021-02-02T06:30:02.662Z] 06:29:29 INFO - results.MissingResultsError: Browsertime cycle missing firstPaint measurement
[task 2021-02-02T06:30:02.662Z] 06:29:29 ERROR - Return code: 1
Comparison of previous successful and recent failing tasks shows this data is missing: `firstPaint: 356ms FCP: 344ms````
Comment 1•4 years ago
|
||
The logging happens in a script of the browsertime library. Successful and failed task both use the artifacts from the same node module task.
Changelog for the Gecko part should be https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=3bdf0c33844f1dc4198f0c44f1ff137b966cdc1d&tochange=7cdfc29ee18774669941d408472b6f03e438734d (based on the Android-Components updates in fenix).
Greg, do you spot anything related to this?
Comment 2•4 years ago
•
|
||
From this log: https://firefoxci.taskcluster-artifacts.net/YyzednpMQouQC4jCuqEmUA/0/public/test_info/logcat-ZY322HN78D.log
02-02 06:07:20.026 8587 8587 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
02-02 06:07:20.030 8587 8587 D AndroidRuntime: CheckJNI is OFF
02-02 06:07:20.134 8587 8587 D ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
02-02 06:07:20.166 8587 8587 I Radio-JNI: register_android_hardware_Radio DONE
02-02 06:07:20.184 8587 8587 D AndroidRuntime: Calling main entry com.android.commands.am.Am
02-02 06:07:20.194 2603 2603 D MediaScannerReceiver: action: android.intent.action.MEDIA_SCANNER_SCAN_FILE path: /storage/emulated/0/browsertime.mp4
02-02 06:07:20.199 8587 8587 D AndroidRuntime: Shutting down VM
02-02 06:07:20.229 8558 8558 D ScreenRecord: success
02-02 06:07:20.311 753 974 I FileSource: StagefrightMetadataRetriever::setDataSource(FD URL suppressed)
02-02 06:07:20.327 752 752 W QComExtractorFactory: Not matched with any sniff above, lets try other sniffs
02-02 06:07:20.328 752 752 E MM_OSAL : Data is not sufficient to validate AAC
02-02 06:07:20.328 752 752 E MM_OSAL : ValidateAACFile data not sufficient
02-02 06:07:22.062 898 898 I MSM-irqbalance: Decided to move IRQ18 from CPU0 [P:0] to CPU6 [P:1] (banned)
02-02 06:07:22.062 898 898 I MSM-irqbalance: Decided to move IRQ18 from CPU2 [P:0] to CPU7 [P:1] (banned)
02-02 06:07:22.063 898 898 I MSM-irqbalance: Decided to move IRQ18 from CPU1 [P:0] to CPU5 [P:1] (banned)
02-02 06:07:22.063 898 898 I MSM-irqbalance: Decided to move IRQ18 from CPU3 [P:0] to CPU4 [P:1] (banned)
02-02 06:07:24.407 758 758 I cnss-daemon: RTM_NEWNEIGH message received: 28
02-02 06:07:24.408 758 758 E cnss-daemon: Stale or unreachable neighbors, ndm state: 16
02-02 06:07:24.433 758 758 I cnss-daemon: RTM_NEWNEIGH message received: 28
02-02 06:07:24.434 758 758 I cnss-daemon: NDA_DST received: 10.7.205.1 ul: 30213898
02-02 06:07:24.434 758 758 I cnss-daemon: NDA_LLADDR received
02-02 06:07:24.570 8150 8187 I Gecko : 1612246044570 Marionette INFO Stopped listening on port 2829
02-02 06:07:24.570 8359 8359 I org.mozilla.fenix: type=1400 audit(0.0:115): avc: denied { write } for uid=10119 comm=4267494F546872656164506F6F6C20 name="startupCache" dev="dm-0" ino=18907 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:shell_data_file:s0:c512,c768 tclass=dir permissive=1
02-02 06:07:24.570 8359 8359 I org.mozilla.fenix: type=1400 audit(0.0:116): avc: denied { add_name } for uid=10119 comm=4267494F546872656164506F6F6C20 name="startupCache.4.little" scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:shell_data_file:s0:c512,c768 tclass=dir permissive=1
02-02 06:07:24.570 8359 8359 I org.mozilla.fenix: type=1400 audit(0.0:117): avc: denied { create } for uid=10119 comm=4267494F546872656164506F6F6C20 name="startupCache.4.little" scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:shell_data_file:s0:c512,c768 tclass=file permissive=1
02-02 06:07:24.574 8473 8473 I org.mozilla.fenix: type=1400 audit(0.0:118): avc: denied { write } for uid=10119 comm=53747265616D5472616E7320233134 name="org.mozilla.fenix-geckodriver-profile" dev="dm-0" ino=18831 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:shell_data_file:s0 tclass=dir permissive=1
02-02 06:07:24.574 8473 8473 I org.mozilla.fenix: type=1400 audit(0.0:119): avc: denied { add_name } for uid=10119 comm=53747265616D5472616E7320233134 name="sessionCheckpoints.json.tmp" scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:shell_data_file:s0 tclass=dir permissive=1
02-02 06:07:24.574 8473 8473 I org.mozilla.fenix: type=1400 audit(0.0:120): avc: denied { remove_name } for uid=10119 comm=53747265616D5472616E7320233134 name="sessionCheckpoints.json" dev="dm-0" ino=18992 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:shell_data_file:s0 tclass=dir permissive=1
02-02 06:07:24.574 8473 8473 I org.mozilla.fenix: type=1400 audit(0.0:121): avc: denied { unlink } for uid=10119 comm=53747265616D5472616E7320233134 name="sessionCheckpoints.json" dev="dm-0" ino=18992 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:shell_data_file:s0:c512,c768 tclass=file permissive=1
02-02 06:07:24.577 8473 8473 I org.mozilla.fenix: type=1400 audit(0.0:122): avc: denied { rename } for uid=10119 comm=53747265616D5472616E7320233134 name="sessionCheckpoints.json.tmp" dev="dm-0" ino=19143 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:shell_data_file:s0:c512,c768 tclass=file permissive=1
02-02 06:07:24.729 8150 8206 I Gecko : [Parent 8150, Unnamed thread 97f27a00] WARNING: waitpid failed pid:8226 errno:10: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_posix.cc:238
02-02 06:07:24.745 1541 2036 I ActivityManager: Process org.mozilla.fenix:tab0 (pid 8226) has died
02-02 06:07:24.745 1541 2036 D ActivityManager: cleanUpApplicationRecord -- 8226
02-02 06:07:24.776 700 8607 D Magisk : su: request from client: 17
02-02 06:07:24.776 700 8607 D Magisk : su: request from uid=[2000] (#1)
02-02 06:07:24.778 700 8607 D Magisk : su_db: query policy=[2]
02-02 06:07:24.778 700 8607 E Magisk : su: cannot find requester
02-02 06:07:24.779 700 8607 D Magisk : su: waiting child: [8608]
02-02 06:07:24.779 8608 8608 D Magisk : su: child process started
02-02 06:07:24.779 8608 8608 D Magisk : su: argc=[3]
02-02 06:07:24.779 8608 8608 D Magisk : su: argv[0]=[su]
02-02 06:07:24.779 8608 8608 D Magisk : su: argv[1]=[-c]
02-02 06:07:24.779 8608 8608 D Magisk : su: argv[2]=[am force-stop org.mozilla.fenix]
02-02 06:07:24.779 8608 8608 D Magisk : su: pts_slave=[/dev/pts/1]
02-02 06:07:24.780 8608 8608 D Magisk : su: stdin using PTY
02-02 06:07:24.780 8608 8608 D Magisk : su: stdout using PTY
02-02 06:07:24.780 8608 8608 D Magisk : su: stderr using PTY
02-02 06:07:24.780 8608 8608 D Magisk : su: use namespace of pid=[8605]
02-02 06:07:25.294 1541 2629 D GraphicsStats: Buffer count: 6
02-02 06:07:25.295 1541 2597 I ActivityManager: Process org.mozilla.fenix (pid 8150) has died
02-02 06:07:25.295 1541 2597 D ActivityManager: cleanUpApplicationRecord -- 8150
02-02 06:07:25.297 1541 2045 W ActivityManager: Ignoring remove of inactive process: ProcessRecord{dd9544e 0:org.mozilla.fenix/u0a119}
02-02 06:07:25.513 8610 8610 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 0 <<<<<<
02-02 06:07:25.518 8610 8610 D AndroidRuntime: CheckJNI is OFF
02-02 06:07:25.523 1541 1635 I WindowManager: Destroying surface Surface(name=Application Error: org.mozilla.fenix) called by com.android.server.wm.WindowStateAnimator.destroySurface:2067 com.android.server.wm.WindowStateAnimator.destroySurfaceLocked:896 com.android.server.wm.WindowState.destroyOrSaveSurface:2094 com.android.server.wm.WindowSurfacePlacer.performSurfacePlacementInner:433 com.android.server.wm.WindowSurfacePlacer.performSurfacePlacementLoop:234 com.android.server.wm.WindowSurfacePlacer.performSurfacePlacement:182 com.android.server.wm.WindowManagerService$H.handleMessage:8191 android.os.Handler.dispatchMessage:102
02-02 06:07:25.526 1541 1635 W AppOps : Finishing op nesting under-run: uid 1000 pkg android code 24 time=0 duration=0 nesting=0
02-02 06:07:25.533 8608 8608 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 0 <<<<<<
02-02 06:07:25.538 8608 8608 D AndroidRuntime: CheckJNI is OFF
02-02 06:07:25.625 8610 8610 D ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
02-02 06:07:25.645 8608 8608 D ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
02-02 06:07:25.666 8610 8610 I Radio-JNI: register_android_hardware_Radio DONE
02-02 06:07:25.685 8610 8610 D AndroidRuntime: Calling main entry com.android.commands.am.Am
02-02 06:07:25.685 8608 8608 I Radio-JNI: register_android_hardware_Radio DONE
02-02 06:07:25.691 1541 1967 E ActivityManager: Sending non-protected broadcast null from system uid 0 pkg null
02-02 06:07:25.691 1541 1967 E ActivityManager: java.lang.Throwable
02-02 06:07:25.691 1541 1967 E ActivityManager: at com.android.server.am.ActivityManagerService.broadcastIntentLocked(ActivityManagerService.java:18222)
02-02 06:07:25.691 1541 1967 E ActivityManager: at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:18817)
02-02 06:07:25.691 1541 1967 E ActivityManager: at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:512)
02-02 06:07:25.691 1541 1967 E ActivityManager: at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2912)
02-02 06:07:25.691 1541 1967 E ActivityManager: at android.os.Binder.execTransact(Binder.java:565)
02-02 06:07:25.693 8610 8610 D AndroidRuntime: Shutting down VM
02-02 06:07:25.704 8608 8608 D AndroidRuntime: Calling main entry com.android.commands.am.Am
02-02 06:07:25.709 1541 2597 I ActivityManager: Force stopping org.mozilla.fenix appid=10119 user=0: from pid 8608
02-02 06:07:25.709 1541 2597 I ActivityManager: Killing 8381:org.mozilla.fenix:mozilla.components.lib.crash.CrashReporter/u0a119 (adj 0): stop org.mozilla.fenix
02-02 06:07:25.709 1541 2597 D ActivityManager: cleanUpApplicationRecord -- 8381
02-02 06:07:25.710 1541 2597 W ActivityManager: Force removing ActivityRecord{73425e u0 org.mozilla.fenix/mozilla.components.lib.crash.prompt.CrashReporterActivity t7434}: app died, no saved state
02-02 06:07:25.722 1541 2594 D GraphicsStats: Buffer count: 5
02-02 06:07:25.723 1541 1770 W InputDispatcher: channel '74c89ed org.mozilla.fenix/mozilla.components.lib.crash.prompt.CrashReporterActivity (server)' ~ Consumer closed input channel or an error occurred. events=0x9
02-02 06:07:25.724 1541 1770 E InputDispatcher: channel '74c89ed org.mozilla.fenix/mozilla.components.lib.crash.prompt.CrashReporterActivity (server)' ~ Channel is unrecoverably broken and will be disposed!
02-02 06:07:25.725 1541 2597 W InputDispatcher: Attempted to unregister already unregistered input channel '74c89ed org.mozilla.fenix/mozilla.components.lib.crash.prompt.CrashReporterActivity (server)'
02-02 06:07:25.729 1541 2597 I WindowManager: Destroying surface Surface(name=org.mozilla.fenix/mozilla.components.lib.crash.prompt.CrashReporterActivity) called by com.android.server.wm.WindowStateAnimator.destroySurface:2067 com.android.server.wm.WindowStateAnimator.destroySurfaceLocked:896 com.android.server.wm.WindowState.removeLocked:1457 com.android.server.wm.WindowManagerService.removeWindowInnerLocked:2531 com.android.server.wm.WindowManagerService.removeWindowLocked:2489 com.android.server.wm.WindowManagerService.removeWindowLocked:2358 com.android.server.wm.AppWindowToken.removeAllWindows:535 com.android.server.wm.AppWindowToken.removeAppFromTaskLocked:331
02-02 06:07:25.743 1541 2629 W WindowManager: Failed looking up window
02-02 06:07:25.743 1541 2629 W WindowManager: java.lang.IllegalArgumentException: Requested window android.os.BinderProxy@28ba004 does not exist
02-02 06:07:25.743 1541 2629 W WindowManager: at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:9212)
02-02 06:07:25.743 1541 2629 W WindowManager: at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:9203)
02-02 06:07:25.743 1541 2629 W WindowManager: at com.android.server.wm.WindowState$DeathRecipient.binderDied(WindowState.java:1798)
02-02 06:07:25.743 1541 2629 W WindowManager: at android.os.BinderProxy.sendDeathNotice(Binder.java:688)
02-02 06:07:25.743 1541 2629 I WindowManager: WIN DEATH: null
02-02 06:07:25.790 1541 2597 I ActivityManager: Killing 8368:org.mozilla.fenix:crashReportingProcess/u0a119 (adj 904): stop org.mozilla.fenix
02-02 06:07:25.791 1541 2597 D ActivityManager: cleanUpApplicationRecord -- 8368
02-02 06:07:25.796 8608 8608 D AndroidRuntime: Shutting down VM
02-02 06:07:25.800 2030 2030 D CarrierSvcBindHelper: No carrier app for: 0
02-02 06:07:25.801 2030 2030 D CarrierSvcBindHelper: No carrier app for: 1
02-02 06:07:25.833 700 8607 D Magisk : su: return code: [0]
02-02 06:07:25.907 700 8636 D Magisk : su: request from client: 14
02-02 06:07:25.907 700 8636 D Magisk : su: request from uid=[2000] (#2)
02-02 06:07:25.907 700 8636 D Magisk : su: waiting child: [8637]
02-02 06:07:25.908 8637 8637 D Magisk : su: child process started
02-02 06:07:25.908 8637 8637 D Magisk : su: argc=[3]
02-02 06:07:25.908 8637 8637 D Magisk : su: argv[0]=[su]
02-02 06:07:25.908 8637 8637 D Magisk : su: argv[1]=[-c]
02-02 06:07:25.908 8637 8637 D Magisk : su: argv[2]=[am clear-debug-app org.mozilla.fenix]
02-02 06:07:25.908 8637 8637 D Magisk : su: pts_slave=[/dev/pts/1]
02-02 06:07:25.908 8637 8637 D Magisk : su: stdin using PTY
02-02 06:07:25.908 8637 8637 D Magisk : su: stdout using PTY
02-02 06:07:25.908 8637 8637 D Magisk : su: stderr using PTY
02-02 06:07:25.909 8637 8637 D Magisk : su: use namespace of pid=[8634]
02-02 06:07:26.024 539 539 I SFPerfTracer: triggers: (rate: 3:455) (compose: 0:2) (post: 0:0) (render: 0:2) (16:1754 frames) (17:1977)
02-02 06:07:26.025 539 539 D SFPerfTracer: layers: (4:11) (StatusBar (0xab8edc00): 17:390) (NavigationBar (0xab8f5000): 17:328) (com.android.systemui.ImageWallpaper (0xab8f6400): 17:328)* (animation background stackId=1 (0xab8ec800): 0:4)* (org.mozilla.fenix/org.mozilla.fenix.HomeActivity (0xab893c00): 0:117)- (SurfaceView - org.mozilla.fenix/org.mozilla.fenix.HomeActivity (0xab8f7800): 0:110)- (SurfaceView - org.mozilla.fenix/org.mozilla.fenix.HomeActivity (0xab8ea000): 0:113)- (com.bitbar.testdroid.monitor/com.bitbar.testdroid.monitor.MainActivity (0xab8eb400): 17:112) (Application Error: org.mozilla.fenix (0xab8f8c00): 0:92)- (org.mozilla.fenix/mozilla.components.lib.crash.prompt.CrashReporterActivity (0xab8bc000): 0:75)- (DimLayerController/Stack=0 (0xab8bd400): 12:28)
Comment 3•4 years ago
|
||
So this part stands out to me, not sure if it's relevant: 02-02 06:07:24.729 8150 8206 I Gecko : [Parent 8150, Unnamed thread 97f27a00] WARNING: waitpid failed pid:8226 errno:10: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_posix.cc:238
Comment 4•4 years ago
|
||
:mcomella, could you or someone else look into this issue? It seems like Fenix is crashing but we can't get any crash dumps from it. You can find the logs in the comment above.
02-02 06:06:09.245 8150 8292 E AndroidRuntime: FATAL EXCEPTION: pool-32-thread-1
02-02 06:06:09.245 8150 8292 E AndroidRuntime: Process: org.mozilla.fenix, PID: 8150
02-02 06:06:09.245 8150 8292 E AndroidRuntime: org.mozilla.experiments.nimbus.ErrorException$ResponseError: Error in network response:
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at org.mozilla.experiments.nimbus.Error.intoException(nimbus.kt:13)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at org.mozilla.experiments.nimbus.NimbusClient.fetchExperiments(nimbus.kt:7)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at mozilla.components.service.nimbus.Nimbus.fetchExperimentsOnThisThread(Nimbus.kt:1)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at mozilla.components.service.nimbus.Nimbus.access$fetchExperimentsOnThisThread(Nimbus.kt:1)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at mozilla.components.service.nimbus.Nimbus$fetchExperiments$1.invokeSuspend(Nimbus.kt:2)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:3)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:15)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
02-02 06:06:09.245 8150 8292 E AndroidRuntime: at java.lang.Thread.run(Thread.java:761)
02-02 06:06:09.259 1541 1967 I ActivityManager: Start proc 8381:org.mozilla.fenix:mozilla.components.lib.crash.CrashReporter/u0a119 for activity org.mozilla.fenix/mozilla.components.lib.crash.prompt.CrashReporterActivity
Nimbus was reintroduced yesterday and it looks like it may be causing the crash. I'm not quite sure the reasoning...
I filed https://github.com/mozilla-mobile/fenix/issues/17762 for the fenix team to address this issue.
Comment 7•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Description
•