chromeos2-devserver5 possibly too slow near 9AM may have caused test failure |
|||
Issue descriptionThis release build: https://uberchromegw.corp.google.com/i/chromeos/builders/wizpig-release/builds/799/steps/PaygenTestCanary/logs/stdio failed in paygentest (paygen) apparently because an autoupdate was too slow: https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/97926982-chromeos-test/chromeos2-row8-rack8-host14/debug/ 01/25 08:58:18.420 INFO |autoupdate_EndToEn:1637| Polling update progress from omaha/devserver: http://100.115.245.197:40851/api/hostlog?ip=100.115.231.33 01/25 08:58:18.420 INFO |autoupdate_EndToEn:0274| Expecting event_result=any version=9219.0.0 event_type=any previous_version=any, within 720 seconds 01/25 08:58:18.534 INFO |autoupdate_EndToEn:0374| Consumed new event: {u'event_result': '1', u'event_type': '54', u'previous_version': '0.0.0.0', u'track': 'stable-channel', u'timestamp': '2017-01-25 08:58:18', u'version': '9219.0.0', u'board': 'wizpig'} 01/25 08:58:18.535 INFO |autoupdate_EndToEn:0301| Event received after 0.0 seconds 01/25 08:58:18.535 INFO |autoupdate_EndToEn:0274| Expecting event_result=1:success version=9219.0.0 event_type=13:download_started previous_version=any, within 240 seconds 01/25 08:58:28.711 INFO |autoupdate_EndToEn:0374| Consumed new event: {u'event_result': '1', u'event_type': '13', u'track': 'stable-channel', u'timestamp': '2017-01-25 08:58:28', u'version': '9219.0.0', u'board': 'wizpig'} 01/25 08:58:28.711 INFO |autoupdate_EndToEn:0301| Event received after 10.1 seconds 01/25 08:58:28.712 INFO |autoupdate_EndToEn:0274| Expecting event_result=1:success version=9219.0.0 event_type=14:download_finished previous_version=any, within 600 seconds 01/25 08:58:59.021 DEBUG| monitors:0191| ts_mon: sending 23 metrics to PubSub 01/25 09:08:29.191 ERROR|autoupdate_EndToEn:0310| Timeout expired 01/25 09:08:29.192 ERROR|autoupdate_EndToEn:0278| Failed expected event: Failed to receive a download finished notification (download_finished) within 600 seconds. This could be a problem with the updater or a connectivity issue. For more details, check the update_engine log (in sysinfo or on the DUT, also included in the test log). The update engine log snippet: [0125/085827:INFO:delta_performer.cc(603)] Starting to apply update payload operations [0125/085857:INFO:delta_performer.cc(167)] Completed 82/883 operations (9%), 65222585/1003998381 bytes downloaded (6%), overall progress 7% [0125/085908:INFO:delta_performer.cc(167)] Completed 106/883 operations (12%), 86407097/1003998381 bytes downloaded (8%), overall progress 10% [0125/085939:INFO:delta_performer.cc(167)] Completed 164/883 operations (18%), 127498169/1003998381 bytes downloaded (12%), overall progress 15% [0125/090010:INFO:delta_performer.cc(167)] Completed 200/883 operations (22%), 156448697/1003998381 bytes downloaded (15%), overall progress 18% [0125/090026:INFO:delta_performer.cc(167)] Completed 212/883 operations (24%), 168490937/1003998381 bytes downloaded (16%), overall progress 20% [0125/090056:INFO:delta_performer.cc(167)] Completed 241/883 operations (27%), 191215545/1003998381 bytes downloaded (19%), overall progress 22% [0125/090126:INFO:delta_performer.cc(167)] Completed 268/883 operations (30%), 216381369/1003998381 bytes downloaded (21%), overall progress 25% [0125/090157:INFO:delta_performer.cc(167)] Completed 288/883 operations (32%), 240613305/1003998381 bytes downloaded (23%), overall progress 27% [0125/090227:INFO:delta_performer.cc(167)] Completed 318/883 operations (36%), 259176377/1003998381 bytes downloaded (25%), overall progress 30% [0125/090257:INFO:delta_performer.cc(167)] Completed 337/883 operations (38%), 282703801/1003998381 bytes downloaded (28%), overall progress 33% [0125/090329:INFO:delta_performer.cc(167)] Completed 362/883 operations (40%), 312719289/1003998381 bytes downloaded (31%), overall progress 35% [0125/090359:INFO:delta_performer.cc(167)] Completed 394/883 operations (44%), 343685049/1003998381 bytes downloaded (34%), overall progress 39% [0125/090414:INFO:delta_performer.cc(167)] Completed 404/883 operations (45%), 361445305/1003998381 bytes downloaded (36%), overall progress 40% [0125/090445:INFO:delta_performer.cc(167)] Completed 425/883 operations (48%), 402094009/1003998381 bytes downloaded (40%), overall progress 44% [0125/090515:INFO:delta_performer.cc(167)] Completed 460/883 operations (52%), 425441209/1003998381 bytes downloaded (42%), overall progress 47% [0125/090546:INFO:delta_performer.cc(167)] Completed 479/883 operations (54%), 450181049/1003998381 bytes downloaded (44%), overall progress 49% [0125/090600:INFO:delta_performer.cc(167)] Completed 489/883 operations (55%), 461846457/1003998381 bytes downloaded (46%), overall progress 50% [0125/090630:INFO:delta_performer.cc(167)] Completed 524/883 operations (59%), 481949625/1003998381 bytes downloaded (48%), overall progress 53% [0125/090701:INFO:delta_performer.cc(167)] Completed 552/883 operations (62%), 504035257/1003998381 bytes downloaded (50%), overall progress 56% [0125/090731:INFO:delta_performer.cc(167)] Completed 576/883 operations (65%), 524253113/1003998381 bytes downloaded (52%), overall progress 58% [0125/090747:INFO:delta_performer.cc(167)] Completed 592/883 operations (67%), 542160825/1003998381 bytes downloaded (54%), overall progress 60% [0125/090817:INFO:delta_performer.cc(167)] Completed 622/883 operations (70%), 564770745/1003998381 bytes downloaded (56%), overall progress 63% -- END ----8<------8<------8<------8<------8<------8<------8<------8<------8<--- suggests that progress was slower than expected. The devserver shows higher utilization at that time, but still 20% idle CPU at worst. (I had to use "sar" because viceroy has a large gap including that time.)
,
Jan 26 2017
Actually I have to take that back. Load average peaked around that time, also later. Linux 4.2.0-27-generic (chromeos2-devserver5) 01/25/2017 _x86_64_ (16 CPU) 12:00:01 AM runq-sz plist-sz ldavg-1 ldavg-5 ldavg-15 blocked 08:05:01 AM 2 600 3.40 2.83 2.42 0 08:10:01 AM 5 644 2.85 2.91 2.58 0 08:15:01 AM 3 632 2.54 2.75 2.61 0 08:20:01 AM 1 593 1.51 1.96 2.31 0 08:25:01 AM 15 651 12.02 5.34 3.42 0 08:30:01 AM 3 615 2.85 4.15 3.50 1 08:35:01 AM 1 594 3.13 3.43 3.34 0 08:40:01 AM 1 591 2.77 3.37 3.35 0 08:45:01 AM 5 618 10.24 5.84 4.23 0 08:50:01 AM 1 603 1.81 3.73 3.82 0 08:55:01 AM 8 676 34.85 21.81 11.18 2 09:05:01 AM 2 569 1.60 4.74 6.93 1 09:10:01 AM 1 539 1.21 2.57 5.39 1 09:15:01 AM 2 549 1.35 1.88 4.32 0 09:20:01 AM 4 556 2.16 1.73 3.56 0 09:25:01 AM 1 559 1.28 1.66 3.05 0 09:30:01 AM 2 560 1.28 1.55 2.63 0 09:35:01 AM 6 556 3.93 2.35 2.64 2 09:40:01 AM 2 558 1.56 1.93 2.38 0 09:45:01 AM 1 551 1.29 1.74 2.19 0 09:50:01 AM 0 531 1.23 1.45 1.94 1 09:55:01 AM 2 595 12.41 6.49 3.71 0 10:05:01 AM 2 558 2.85 2.88 3.01 0 10:10:01 AM 38 692 41.56 20.34 9.67 0 10:15:01 AM 2 674 3.58 12.27 9.52 0 10:20:01 AM 14 709 15.56 13.20 10.46 0 10:25:01 AM 8 630 4.76 7.87 8.93 0 10:30:01 AM 2 585 2.57 4.87 7.39 1 10:35:01 AM 1 557 1.21 2.77 5.81 0 10:40:01 AM 1 553 1.76 2.35 4.80 0 10:45:01 AM 1 567 1.36 2.08 4.04 0 10:50:01 AM 3 557 1.75 1.89 3.42 0 10:55:01 AM 1 641 34.40 24.51 12.69 0 11:05:01 AM 1 560 3.28 5.68 7.88 0 11:10:01 AM 2 548 1.65 3.03 6.11 0 11:15:01 AM 20 629 15.07 6.33 6.33 1 11:20:01 AM 1 615 2.28 4.36 5.58 1 11:25:01 AM 3 554 1.34 2.69 4.53 0 11:30:01 AM 2 537 1.19 1.84 3.66 0
,
Feb 16 2017
,
Jun 28 2017
Sadly incident bugs like this exponentially lose value, imo. If we didn't get something by looking at this at that time, it's unlikely we will now (unless we're collecting evidence for some theory) |
|||
►
Sign in to add a comment |
|||
Comment 1 by semenzato@chromium.org
, Jan 26 2017