Closed Bug 1644933 Opened 5 years ago Closed 5 years ago

Perma fail Android btime vismet Couldn't get activedata data | Failed to find a live site variant

Categories

(Testing :: Performance, defect)

Product:
Testing
Component:
Performance
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1633332

People

(Reporter: bogdan_tara, Unassigned)

Details

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=305881120&repo=mozilla-central&lineNumber=1019

https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/f8IPU12DRW-SUQ9w-Tq9Ww/runs/1/artifacts/public/logs/live_backing.log

[task 2020-06-11T00:47:32.282Z] Input #0, mov,mp4,m4a,3gp,3g2,mj2, from '/builds/worker/fetches/browsertime-results/bbc/pages/www.bbc.com/news/business-47245877/query-574d248d/data/video/1.mp4':
[task 2020-06-11T00:47:32.282Z]   Metadata:
[task 2020-06-11T00:47:32.282Z]     major_brand     : isom
[task 2020-06-11T00:47:32.282Z]     minor_version   : 512
[task 2020-06-11T00:47:32.282Z]     compatible_brands: isomiso2avc1mp41
[task 2020-06-11T00:47:32.282Z]     encoder         : Lavf58.20.100
[task 2020-06-11T00:47:32.282Z]   Duration: 00:00:05.76, start: 0.000000, bitrate: 287 kb/s
[task 2020-06-11T00:47:32.282Z]     Stream #0:0(und): Video: h264 (High) (avc1 / 0x31637661), yuv420p, 1080x1584, 285 kb/s, 2.43 fps, 25 tbr, 12800 tbn, 50 tbc (default)
[task 2020-06-11T00:47:32.282Z]     Metadata:
[task 2020-06-11T00:47:32.282Z]       handler_name    : VideoHandler
[task 2020-06-11T00:47:32.283Z] Stream mapping:
[task 2020-06-11T00:47:32.283Z]   Stream #0:0 -> #0:0 (h264 (native) -> png (native))
[task 2020-06-11T00:47:32.283Z] Press [q] to stop, [?] for help
[task 2020-06-11T00:47:32.371Z] Output #0, image2, to '/tmp/vis-igH6Rl/viewport.png':
[task 2020-06-11T00:47:32.371Z]   Metadata:
[task 2020-06-11T00:47:32.371Z]     major_brand     : isom
[task 2020-06-11T00:47:32.371Z]     minor_version   : 512
[task 2020-06-11T00:47:32.371Z]     compatible_brands: isomiso2avc1mp41
[task 2020-06-11T00:47:32.371Z]     encoder         : Lavf58.20.100
[task 2020-06-11T00:47:32.371Z]     Stream #0:0(und): Video: png, rgb24, 1080x1584, q=2-31, 200 kb/s, 25 fps, 25 tbn, 25 tbc (default)
[task 2020-06-11T00:47:32.371Z]     Metadata:
[task 2020-06-11T00:47:32.371Z]       handler_name    : VideoHandler
[task 2020-06-11T00:47:32.371Z]       encoder         : Lavc58.35.100 png
[task 2020-06-11T00:47:32.414Z] frame=    1 fps=0.0 q=-0.0 Lsize=N/A time=00:00:00.04 bitrate=N/A speed=0.307x    
[task 2020-06-11T00:47:32.414Z] video:8kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
[task 2020-06-11T00:47:34.658Z] 2020-06-11T00:47:34.658249Z Command succeeded              result=b'{"SpeedIndex": 1051, "FirstVisualChange": 440, "LastVisualChange": 1400, "VisualProgress": "0=0, 440=24, 520=24, 560=24, 760=24, 1240=98, 1320=98, 1400=100", "ContentfulSpeedIndex": 462, "videoRecordingStart": 2040, "ContentfulSpeedIndexProgress": "0=0, 440=95, 520=96, 560=97, 760=99, 1240=100, 1320=100, 1400=100", "PerceptualSpeedIndex": 1041, "PerceptualSpeedIndexProgress": "0=0, 440=42, 520=47, 560=50, 760=64, 1240=98, 1320=99, 1400=100"}\n'
[task 2020-06-11T00:47:35.191Z] 2020-06-11T00:47:35.191165Z Command succeeded              result=b'{"SpeedIndex": 792, "FirstVisualChange": 320, "LastVisualChange": 1320, "VisualProgress": "0=0, 320=24, 400=24, 440=24, 760=24, 920=93, 1080=98, 1200=98, 1320=100", "ContentfulSpeedIndex": 355, "videoRecordingStart": 2000, "ContentfulSpeedIndexProgress": "0=0, 320=90, 400=91, 440=92, 760=98, 920=99, 1080=99, 1200=100, 1320=100", "PerceptualSpeedIndex": 818, "PerceptualSpeedIndexProgress": "0=0, 320=39, 400=46, 440=49, 760=78, 920=92, 1080=96, 1200=98, 1320=100"}\n'
[task 2020-06-11T00:47:35.333Z] 2020-06-11T00:47:35.333228Z Command succeeded              result=b'{"SpeedIndex": 929, "FirstVisualChange": 320, "LastVisualChange": 1200, "VisualProgress": "0=0, 320=24, 400=24, 480=24, 640=24, 1040=24, 1120=98, 1200=100", "ContentfulSpeedIndex": 351, "videoRecordingStart": 2040, "ContentfulSpeedIndexProgress": "0=0, 320=91, 400=92, 480=94, 640=97, 1040=100, 1120=100, 1200=100", "PerceptualSpeedIndex": 910, "PerceptualSpeedIndexProgress": "0=0, 320=35, 400=41, 480=47, 640=60, 1040=92, 1120=98, 1200=100"}\n'
[task 2020-06-11T00:47:36.147Z] 2020-06-11T00:47:36.147238Z Command succeeded              result=b'{"SpeedIndex": 960, "FirstVisualChange": 320, "LastVisualChange": 1280, "VisualProgress": "0=0, 320=24, 440=24, 640=24, 1040=24, 1160=98, 1280=100", "ContentfulSpeedIndex": 351, "videoRecordingStart": 2040, "ContentfulSpeedIndexProgress": "0=0, 320=91, 440=93, 640=96, 1040=100, 1160=100, 1280=100", "PerceptualSpeedIndex": 943, "PerceptualSpeedIndexProgress": "0=0, 320=33, 440=43, 640=58, 1040=89, 1160=98, 1280=100"}\n'
[task 2020-06-11T00:47:36.756Z] 2020-06-11T00:47:36.756031Z Found 25 new videos
[task 2020-06-11T00:47:36.756Z] 2020-06-11T00:47:36.756518Z Querying Active-data...
[task 2020-06-11T00:47:41.751Z] 2020-06-11T00:47:41.751620Z Status: {'200'}
[task 2020-06-11T00:47:41.791Z] 2020-06-11T00:47:41.791836Z Found 19 datums
[task 2020-06-11T00:47:41.791Z] 2020-06-11T00:47:41.791960Z Comparing videos to TASK_GROUP=HjXKAlzvSLK_b1Zn-0BfuQ, TASK_ID=FlZQiJT4Q5i2v0oL1O6JOQ
[task 2020-06-11T00:47:41.792Z] 2020-06-11T00:47:41.792116Z Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FlZQiJT4Q5i2v0oL1O6JOQ/artifacts/public/test_info/browsertime-results.tgz
[task 2020-06-11T00:47:42.336Z] 2020-06-11T00:47:42.336432Z Found 25 old videos
[task 2020-06-11T00:50:11.025Z] 2020-06-11T00:50:11.025495Z Average 3D similarity: 0.90822
[task 2020-06-11T00:50:11.025Z] 2020-06-11T00:50:11.025581Z Average 2D similarity: 0.89161
[task 2020-06-11T00:50:11.025Z] 2020-06-11T00:50:11.025787Z Querying Active-data...
[task 2020-06-11T00:50:13.475Z] 2020-06-11T00:50:13.475037Z Status: {'200'}
[task 2020-06-11T00:50:13.475Z] 2020-06-11T00:50:13.475260Z Couldn't get activedata data
[task 2020-06-11T00:50:13.475Z] 2020-06-11T00:50:13.475342Z Failed to find a live site variant
[task 2020-06-11T00:50:13.478Z] 2020-06-11T00:50:13.478056Z PERFHERDER_DATA: {"framework": {"name": "browsertime"}, "application": {"name": "geckoview"}, "type": "vismet", "suites": [{"name": "bbc", "subtests": [{"name": "SpeedIndex", "replicates": [1754, 1223, 954, 1293, 810, 971, 914, 921, 1079, 1041, 1021, 790, 1078, 1100, 1260, 872, 1139, 831, 800, 982, 1051, 792, 929, 960], "lowerIsBetter": true, "unit": "ms", "value": 976.5}, {"name": "FirstVisualChange", "replicates": [1400, 400, 360, 560, 320, 360, 440, 440, 320, 280, 440, 280, 440, 400, 440, 320, 440, 360, 320, 400, 440, 320, 320, 320], "lowerIsBetter": true, "unit": "ms", "value": 380.0}, {"name": "LastVisualChange", "replicates": [3640, 1600, 1440, 1720, 1520, 1320, 1440, 1520, 1320, 1360, 1400, 1400, 1280, 1360, 1520, 1320, 1360, 1320, 1360, 1400, 1400, 1320, 1200, 1280], "lowerIsBetter": true, "unit": "ms", "value": 1380.0}, {"name": "ContentfulSpeedIndex", "replicates": [1516, 440, 399, 595, 355, 382, 473, 476, 360, 319, 461, 315, 473, 437, 478, 342, 476, 391, 356, 426, 462, 355, 351, 351], "lowerIsBetter": true, "unit": "ms", "value": 412.5}, {"name": "videoRecordingStart", "replicates": [2040, 2040, 2040, 2040, 2040, 2000, 2000, 2000, 2000, 2040, 2000, 2040, 2040, 2040, 2040, 2040, 2040, 2000, 2000, 2040, 2040, 2000, 2040, 2040], "lowerIsBetter": true, "unit": "ms", "value": 2040.0}, {"name": "PerceptualSpeedIndex", "replicates": [2626, 1195, 967, 1281, 863, 961, 941, 959, 1037, 1012, 1017, 825, 1045, 1070, 1213, 879, 1105, 852, 834, 983, 1041, 818, 910, 943], "lowerIsBetter": true, "unit": "ms", "value": 975.0}, {"name": "Similarity", "value": 0.90822, "replicates": [0.90822], "lowerIsBetter": false, "unit": "a.u."}, {"name": "Similarity2D", "value": 0.89161, "replicates": [0.89161], "lowerIsBetter": false, "unit": "a.u."}], "extraOptions": []}]}
[fetches 2020-06-11T00:50:14.320Z] removing /builds/worker/fetches
[fetches 2020-06-11T00:50:14.328Z] finished
[taskcluster 2020-06-11 00:50:14.627Z] === Task Finished ===
[taskcluster 2020-06-11 00:50:14.996Z] Unsuccessful task run with exit code: 1 completed in 205.031 seconds

Could this be caused by bug 1630675?

Flags: needinfo?(aionescu)

Will investigate asap.

Flags: needinfo?(aionescu)

Seems like the autoland perma was fixed by the backout of Bug 1557718 (b9853d5eb007 - landed 1557718, up next perma 1177ebce20f8 - just the one after my patch, dab3c58da8d2 - backout of 1557718, fab7c4f54054 - perma fixed) which didn't landed yet on m-c. Shall we wait?

Flags: needinfo?(btara)

The actual failure here is this line - note how the failure in the activedata query didn't cause a task failure since we still output perfherder data:
[task 2020-06-11T00:47:17.865Z] 2020-06-11T00:47:17.864200Z Command failed cmd=['/usr/bin/python', '/builds/worker/fetches/visualmetrics.py', '--video', '/builds/worker/fetches/browsertime-results/bbc/pages/www.bbc.com/news/business-47245877/query-5cbc55ea/data/video/1.mp4', '--orange', '--perceptual', '--contentful', '--force', '--renderignore', '5', '--json', '--viewport'] output=b'' status=1

Or this error:
[task 2020-06-11T00:47:21.596Z] 2020-06-11T00:47:21.595877Z Failed to run visualmetrics.py error=b'' video_path=PosixPath('/builds/worker/fetches/browsertime-results/bbc/pages/www.bbc.com/news/business-47245877/query-5cbc55ea/data/video/1.mp4')

It's odd that this line doesn't show up in the treeherder display.

No longer regressed by: 1630675
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → DUPLICATE

Thank your for the analysis sparky.

Flags: needinfo?(btara)
You need to log in before you can comment on or make changes to this bug.