Closed Bug 981995 Opened 12 years ago Closed 11 years ago

regression in cold_load_time for multiple apps

Categories

(Firefox OS Graveyard :: Performance, defect, P1)

Product:
Firefox OS Graveyard
Component:
Performance
Platform:
ARM
Gonk (Firefox OS)
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME
Milestone:
2.0 S3 (6june)

People

(Reporter: huseby, Assigned: Eli)

Details

(Keywords: perf, regression, Whiteboard: [c=regression p=4 s= u=] [b2gperf_regression])

We just noticed at regression in cold_load_time for Settings, Gallery, Usage, Message, Contacts, and Camera ranging between 30ms and 150ms. The regression range is: gecko.git: f60c92c019cd9fe3 to 259c357e28044efe
(In reply to Dave Huseby [:huseby] from comment #0) > We just noticed at regression in cold_load_time for Settings, Gallery, > Usage, Message, Contacts, and Camera ranging between 30ms and 150ms. > > The regression range is: > > gecko.git: f60c92c019cd9fe3 to 259c357e28044efe Those gecko commits don't exist in hg. Is this worth noming as well?
Here are numbers from my Peak that I had ready to go: APZ+Tiles: Results for Gallery, cold_load_time: median:639, mean:638, std: 16, max:672, min:607 APZ: Results for Gallery, cold_load_time: median:637, mean:638, std: 27, max:727, min:560 Tiles: Results for Gallery, cold_load_time: median:618, mean:623, std: 23, max:682, min:586 Neither: Results for Gallery, cold_load_time: median:619, mean:619, std: 30, max:698, min:552 APZ+Tiles: Results for Video, cold_load_time: median:825, mean:821, std: 28, max:866, min:750 APZ: Results for Video, cold_load_time: median:816, mean:812, std: 34, max:870, min:702 Tiles: Results for Video, cold_load_time: median:834, mean:821, std: 47, max:898, min:679 Neither: Results for Video, cold_load_time: median:818, mean:810, std: 38, max:876, min:700 I'm not really seeing the regression on the Peak platform. Checking Hamachi now.
Assignee: nobody → dhuseby
Status: NEW → ASSIGNED
It doesn't look like the APZ and/or tiles feature is the cause of the regression. Here are the numbers from the Hamachi Video app: APZ + Tiles: Results for Video, cold_load_time: median:1236, mean:1238, std: 27, max:1353, min:1207 APZ: Results for Video, cold_load_time: median:1243, mean:1256, std: 63, max:1572, min:1190 Tiles: Results for Video, cold_load_time: median:1201, mean:1216, std: 65, max:1544, min:1169 neither: Results for Video, cold_load_time: median:1206, mean:1217, std: 60, max:1519, min:1167 These numbers are consistently 200ms higher than the pre-regression numbers of ~1000ms cold launch time for the Video app. The regression must have bean caused by something else. This is going to take some digging.
Priority: -- → P1
Whiteboard: [c=progress p= s= u=] [b2gperf_regression] → [c=progress p=4 s= u=] [b2gperf_regression]
Component: General → Performance
Assignee: dhuseby → hub
Is this still an issue or actionable at all?
Flags: needinfo?(hub)
Flags: needinfo?(dhuseby)
I haven't been able to regress it. I get timings off the charts in every case on hamachi.
Flags: needinfo?(hub)
We need to bisect this.
Flags: needinfo?(dhuseby)
Assignee: hub → mchang
Since no gaia revision is listed, I'm trying one from March 11, 2014. Gaia rev: 3f70399569d0c56a399dbca85b3469c2ce3fa503 Gecko range: 7a2edc5171e6 - d01bf8596d3b Not sure which is good / bad yet.
Good 7a2edc5171e6 Results for Video, cold_load_time: median:969, mean:977, std: 101, max:1126, min:852, all:1093,1114,1105,1114,1126,1094,1077,995,993,953,986,896,864,876,911,867,868,852,881,886 Bad d01bf8596d3b Results for Video, cold_load_time: median:1224, mean:1231, std: 34, max:1334, min:1183, all:1250,1252,1228,1205,1244,1226,1195,1276,1183,1232,1279,1334,1221,1202,1205,1220,1204,1239,1212,1222
From bisection: The first bad revision is: changeset: 172501:0d70e6efa22c parent: 172477:8b82f5009d14 parent: 172500:01d7be943857 user: Ryan VanderMeulen <ryanvm@gmail.com> date: Fri Mar 07 15:26:12 2014 -0500 summary: Merge fx-team to m-c. hg said I could continue along the ancestors, I'm doing that now.
When I went down the ancestors, hg bisect couldn't find anything as all the ancestors weren't showing the regression. Ryan, any idea or bug number this commit from comment 10 was from?
Flags: needinfo?(ryanvm)
Current gaia / gecko tip results - Results for Video, cold_load_time: median:1445, mean:1459, std: 44, max:1570, min:1402, all:1570,1544,1423,1456,1441,1498,1429,1446,1494,1421,1445,1402,1455,1442,1543,1432,1446,1431,1430,1448 150ms delay comes from bug 950673.
If I understand you correctly from comment 10, you've got it narrowed down this far on m-c already: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=7a2edc5171e6&tochange=0d70e6efa22c Rev 0d70e6efa22c was a branch merge from fx-team to m-c. We have 3 different integration branches that merge into m-c - mozilla-inbound, b2g-inbound, and fx-team. Due to history being non-linear, it can be a bit tricky to track things down. Things seem to be a bit screwy, but the below link looks like a roughly-equivalent range over fx-team: https://hg.mozilla.org/integration/fx-team/pushloghtml?fromchange=f6a9862a0d2b&tochange=01d7be943857 If I had to wager a guess, hg is getting a bit confused going down the ancestors on m-c. Try bisecting on fx-team over the above range and see if you get better results. Though I'd have to say that I'd be quite surprised if this is really a regression from something that landed there, because things that land there are rarely relevant to B2G at all, which makes me a bit suspicious of your narrowed-down m-c regression range. I did a quick scan of the csets in that range and nothing stands out to me.
Flags: needinfo?(ryanvm)
From comment 13, I tried bisecting fx-team. It doesn't look like bisecting has come up with anything. Hamachi fx-team 01d7be943857 - f6a9862a0d2b gaia 3f70399569d0c56a399dbca85b3469c2ce3fa503 Starting 01d7be943857 Results for Video, cold_load_time: median:1086, mean:1084, std: 16, max:1132, min:1046, all:1132,1097,1069,1086,1096,1103,1101,1064,1096,1098,1046,1095,1078,1104,1092,1063,1085,1060,1081,1073,1089,1078,1079,1073,1088,1064,1096,1093,1082,1087 172327:f6a9862a0d2b Results for Video, cold_load_time: median:1097, mean:1100, std: 12, max:1125, min:1080, all:1124,1100,1113,1090,1096,1108,1094,1106,1097,1097,1085,1096,1103,1097,1114,1125,1116,1113,1098,1103,1089,1086,1088,1096,1081,1080,1098,1117,1122,1087
I tried bissecting from scratch again. All the numbers dropped from ~1300 ms for the bad version, and ~1100 for the good to ~1100 for hte bad and ~850 for the good. The results are confusing, so I'm leaving the bisection trail here. But at least we got another commit. 172533:99e60b1adf71 Results for Video, cold_load_time: median:1033, mean:1035, std: 29, max:1125, min:978, all:1125,1054,1038,1069,1056,1051,1061,1080,1051,1074,1063,1041,1030,997,1005,1039,1014,1028,1008,1028,1009,1007,1019,1037,1016,1017,1015,1011,1048,978 Testing changeset 172500:01d7be943857 (28 changesets remaining, ~4 tests) Results for Video, cold_load_time: median:859, mean:868, std: 49, max:1060, min:810, all:1060,1002,810,849,885,890,849,871,886,838,837,840,894,867,862,861,861,858,865,850,852,880,850,818,879,829,842,823,910,833 Testing changeset 172528:9c88a32cffb0 (14 changesets remaining, ~3 tests)o Results for Video, cold_load_time: median:1065, mean:1067, std: 22, max:1155, min:1039, all:1155,1092,1054,1065,1066,1054,1089,1059,1085,1053,1043,1101,1067,1050,1058,1067,1069,1074,1053,1066,1065,1039,1052,1055,1077,1040,1057,1086,1060,1075 172524:6175ca5a9da4 Results for Video, cold_load_time: median:1018, mean:1020, std: 18, max:1065, min:990, all:1065,1016,1032,1032,1044,1002,998,1016,990,1034,1047,1024,1020,1014,999,1010,1007,992,1035,1017,1030,1020,1002,1015,1022,1005,1052,998,1024,1049 172522:744810b79570 Results for Video, cold_load_time: median:860, mean:910, std: 86, max:1114, min:822, all:1069,1017,1051,1014,1114,1038,1011,1005,942,822,879,884,843,877,842,891,844,833,990,860,855,842,825,851,850,841,860,852,854,860 172523:2429468e82dd (2 changesets remaining, ~1 tests) Results for Video, cold_load_time: median:1031, mean:1032, std: 21, max:1106, min:998, all:1106,1047,1018,1041,1008,1018,998,1010,1049,1057,1020,1037,1030,1032,1038,1024,1021,1007,1015,1048,1059,1038,1052,1023,1023,1033,1005,1039,1021,1050 The first bad revision is: changeset: 172523:2429468e82dd user: Michael Wu <mwu@mozilla.com> date: Mon Feb 24 22:37:51 2014 -0500 summary: Bug 962670 - Store decoded images in VolatileBuffers, r=seth,jrmuizel Results for Video, cold_load_time: median:1012, mean:1020, std: 34, max:1117, min:978, all:1084,1030,1012,1006,1117,1037,1047,1007,1017,1030,1063,996,1090,1075,1010,1018,1023,992,989,992,995,1000,988,979,998,978,1029,1019,1012,995 Repeat results for 744810b79570 Results for Video, cold_load_time: median:853, mean:893, std: 87, max:1115, min:821, all:1115,1018,1005,1003,1038,1064,1071,852,840,917,870,826,867,836,830,862,849,841,861,851,822,833,854,870,835,834,821,826,866,831
Huseby, can you try to reproduce these numbers please on a hamachi. Gaia: 3f70399569d0c56a399dbca85b3469c2ce3fa503 Good Gecko: 172522:744810b79570 Results for Video, cold_load_time: median:860, mean:910, std: 86, max:1114, min:822, all:1069,1017,1051,1014,1114,1038,1011,1005,942,822,879,884,843,877,842,891,844,833,990,860,855,842,825,851,850,841,860,852,854,860 Bad Gecko: 172523:2429468e82dd Results for Video, cold_load_time: median:1012, mean:1020, std: 34, max:1117, min:978, all:1084,1030,1012,1006,1117,1037,1047,1007,1017,1030,1063,996,1090,1075,1010,1018,1023,992,989,992,995,1000,988,979,998,978,1029,1019,1012,995
Flags: needinfo?(dhuseby)
Whiteboard: [c=progress p=4 s= u=] [b2gperf_regression] → [c=regression p=4 s= u=] [b2gperf_regression]
Gaia: 3f70399569d0c56a399dbca85b3469c2ce3fa503 Good Gecko: 005fa75 (hg: 744810b79570) Results for Video, cold_load_time: median:1099, mean:1106, std: 34, max:1223, min:1044, all:1175,1087,1108,1086,1209,1100,1083,1103,1086,1099,1095,1044,1098,1095,1223,1096,1092,1096,1111,1111,1106,1096,1109,1108,1112,1079,1107,1099,1105,1090 Bad Gecko: d65ac2b (hg: 2429468e82dd) Results for Video, cold_load_time: median:1087, mean:1092, std: 23, max:1174, min:1057, all:1120,1095,1098,1089,1155,1108,1089,1117,1086,1074,1087,1074,1086,1080,1080,1061,1094,1174,1107,1079,1087,1090,1073,1086,1057,1069,1080,1098,1093,1085 My numbers don't match.
Flags: needinfo?(dhuseby)
I'm still not able to reproduce now, even starting from scratch with the bad gecko in comment 9. Bad d01bf8596d3b Results for Video, cold_load_time: median:916, mean:948, std: 101, max:1288, min:870, all:1288,1226,1222,904,917,909,925,908,912,905,915,914,937,885,994,937,901,940,928,922,922,889,898,925,908,921,903,870,929,900 Results for Video, cold_load_time: median:969, mean:1031, std: 199, max:1868, min:886, all:1273,1265,1274,1252,1254,1002,994,1005,941,1038,1012,1005,914,1001,999,919,902,907,916,903,899,928,921,896,954,1868,919,909,886,985 Good 7a2edc5171e6 Results for Video, cold_load_time: median:969, mean:976, std: 68, max:1170, min:871, all:1170,1109,1104,977,982,923,983,980,964,962,941,1030,1005,1024,981,964,979,1041,965,974,958,956,964,1039,871,882,872,895,914,886 Results for Video, cold_load_time: median:965, mean:971, std: 102, max:1131, min:835, all:1098,1082,1084,1109,1076,1131,1070,1086,1062,1076,1062,1058,987,964,1066,967,843,875,851,899,871,888,870,873,878,835,847,891,878,860
Huseby, can you please try one last set on a hamachi. Gaia: 3f70399569d0c56a399dbca85b3469c2ce3fa503 Good Gecko: 7a2edc5171e6 Bad Gecko: d01bf8596d3b Thanks!
Flags: needinfo?(dhuseby)
sure, trying now.
Flags: needinfo?(dhuseby)
Gaia: 3f70399 Good Gecko: f60c92c (hg: 7a2edc5171e6) Results for Video, cold_load_time: median:1095, mean:1101, std: 23, max:1200, min:1072, all:1123,1085,1098,1093,1200,1128,1081,1104,1098,1117,1079,1091,1094,1081,1096,1099,1095,1138,1111,1110,1085,1083,1095,1076,1072,1089,1110,1090,1108,1103 Bad Gecko: 259c357 (hg: d01bf8596d3b) Results for Video, cold_load_time: median:1218, mean:1225, std: 39, max:1407, min:1180, all:1267,1207,1279,1213,1213,1249,1216,1227,1199,1201,1180,1220,1407,1220,1230,1195,1226,1210,1209,1207,1233,1232,1208,1233,1230,1201,1235,1201,1241,1188 well, there's the regression again.
Flags: needinfo?(mchang)
Can you try running each version 3 times with b2gperf? Each set has 30 iterations?
Flags: needinfo?(dhuseby)
Flags: needinfo?(mchang)
Assignee: mchang → eperelman
new numbers...4 runs each, 30 iterations: good gecko f60c92c Results for Video, cold_load_time: median:975, mean:979, std: 93, max:1213, min:851, all:1134,1090,1101,1206,998,1002,974,963,973,990,960,1038,975,974,979,1213,990,975,964,975,978,879,863,851,899,991,874,863,859,855 Results for Video, cold_load_time: median:1100, mean:1362, std: 482, max:2376, min:1075, all:1146,1222,1100,1093,2376,1090,1075,2356,1100,1093,2372,1082,1094,1116,1106,1112,1094,1091,1834,1088,1094,1843,1161,1082,2331,1104,1090,2367,1091,1076 Results for Video, cold_load_time: median:1105, mean:1373, std: 435, max:2363, min:1072, all:1125,2356,1212,1108,1818,1103,1097,1840,1099,1086,1870,1085,1099,1805,1093,1100,2363,1072,1107,1831,1091,1121,2347,1087,1102,1810,1093,1085,1081,1107 Results for Video, cold_load_time: median:1104, mean:1356, std: 433, max:2433, min:1055, all:1137,1188,1100,1082,2338,1081,1098,1838,1102,1084,1866,1125,1091,2433,1103,1095,1104,1105,1818,1055,1083,1815,1100,1175,1807,1238,1081,2365,1077,1107 bad gecko 259c357 Results for Video, cold_load_time: median:1014, mean:1074, std: 116, max:1389, min:967, all:1279,1217,1297,1208,1186,1230,1047,989,1041,1037,975,989,1005,967,1389,999,991,1080,1016,1109,972,1013,984,994,1229,1013,980,993,1015,988 Results for Video, cold_load_time: median:1242, mean:1247, std: 35, max:1417, min:1210, all:1276,1245,1211,1212,1256,1259,1238,1236,1241,1239,1227,1249,1242,1236,1213,1256,1260,1231,1262,1259,1248,1235,1236,1265,1220,1243,1242,1417,1274,1210 Results for Video, cold_load_time: median:1219, mean:1222, std: 23, max:1290, min:1177, all:1290,1235,1211,1226,1196,1191,1232,1223,1208,1204,1239,1256,1203,1268,1205,1229,1254,1203,1231,1177,1209,1210,1246,1200,1222,1228,1216,1239,1208,1215 Results for Video, cold_load_time: median:1214, mean:1220, std: 24, max:1320, min:1186, all:1267,1226,1211,1235,1212,1215,1193,1208,1245,1208,1225,1199,1219,1213,1320,1247,1210,1214,1222,1186,1219,1205,1229,1238,1217,1211,1203,1219,1201,1210
Flags: needinfo?(dhuseby) → needinfo?(mchang)
I can't explain the first run of the bad gecko, but it settled on ~1220 median time for the last three runs. A similar thing happened with the first run of the good gecko too. Weird. I have no idea why that's happening. I rebooted the phone between each run.
I will try and replicate this on Monday with my Flame.
Flags: needinfo?(mchang) → needinfo?(eperelman)
3 runs each on a Flame: good gecko f60c92c: Results for Video, cold_load_time: median:473, mean:476, std: 18, max:533, min:455, all:496,462,495,460,481,463,496,459,459,458,510,482,510,457,482,471,465,460,469,458,473,464,479,455,474,481,481,481,533,492 Results for Video, cold_load_time: median:473, mean:481, std: 22, max:544, min:450, all:494,471,474,500,468,479,467,473,467,480,518,476,485,450,463,452,485,468,521,489,470,459,471,496,528,470,465,462,544,485 Results for Video, cold_load_time: median:475, mean:480, std: 18, max:533, min:457, all:477,474,512,500,472,475,526,533,471,477,478,471,457,464,459,462,475,492,479,513,471,461,470,473,476,488,471,488,475,472 --- bad gecko 259c357: Results for Video, cold_load_time: median:496, mean:504, std: 21, max:561, min:468, all:504,495,491,499,536,495,514,481,499,561,486,490,493,534,496,495,497,485,468,492,496,533,521,489,506,499,515,548,488,541 Results for Video, cold_load_time: median:498, mean:506, std: 25, max:571, min:470, all:558,525,511,527,483,522,501,472,492,509,485,571,486,488,496,484,470,539,529,545,485,487,496,534,484,482,523,507,493,525 Results for Video, cold_load_time: median:493, mean:502, std: 22, max:554, min:477, all:511,530,480,524,550,477,490,513,486,483,495,538,497,492,554,482,534,477,490,510,478,503,488,493,488,533,493,492,514,490 --- I see an approximate 30-second regression on my Flame.
Flags: needinfo?(eperelman)
In trying to bisect this, the numbers for every rev between good and bad were comparable on the Flame. I can't seem to reproduce this issue reliably. After discussing with Mason, we feel that this is no longer an issue with the latest releases.
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
Resolution: --- → WORKSFORME
Target Milestone: --- → 2.0 S3 (6june)
You need to log in before you can comment on or make changes to this bug.