tree 710d2a199a01f3240679d17489ca9b3f162bf0b0
parent d793606f2d46f5020669ecf24af2f4a3bb446b30
author Gilad Arnold <garnold@chromium.org> 1358282105 -0800
committer ChromeBot <chrome-bot@google.com> 1359055479 -0800

AU: improve progress logging during updates

We currently emit a log message for operations at fixed index increments
of 1000. This is fairly useful in keeping the number of log messages
small, but otherwise quite arbitrary and useless in giving an actual
sense of progress, throughput, etc for updates of varying number of
operations in them and subject to network latencies.  Further, this
progress report does not take into the account the download progress,
which appears to be the completion metric used toward the UI.

This CL proposes a simple mechanism for computing an "overall update
progress" and an adaptive method for emitting a progress log message in
reasonable intervals. The raw metrics currently used include (i) the
number of bytes downloaded out of the expected total; (ii) the number of
operations successfully applied out of the expected total.  These are
weighed into a single percentage counter based on a prefixed set of
weights.  Logging occurs based on either (i) completion of update
"chunks" of some predetermined number; or (ii) having enough time
elapsed since the last log message.  This guarantees that we'll see
enough progress messages at regular intervals, but not too many of them.

We're also similarly logging the relative position in a resumed update
right before we start applying from the point we left it.

Note that the max number of regular log intervals, as well as the
timeout to force a progress log, can be easily tweaked by changing
compile-time constants.  They are currently set to 10 (or every 10%) and
30 (for 30 seconds since the last progress log), respectively, which
appear to be a reasonable choices.

Here's an example from an actual update log:

[0118/145759:INFO:delta_performer.cc(451)] Starting to apply update payload operations
[0118/145821:INFO:delta_performer.cc(150)] Completed 100/1040 operations (9%), 38363576/319659860 bytes downloaded (12%), overall progress 10%
[0118/145835:INFO:delta_performer.cc(150)] Completed 213/1040 operations (20%), 63939000/319659860 bytes downloaded (20%), overall progress 20%
[0118/145857:INFO:delta_performer.cc(150)] Completed 298/1040 operations (28%), 102293944/319659860 bytes downloaded (32%), overall progress 30%
[0118/145912:INFO:delta_performer.cc(150)] Completed 421/1040 operations (40%), 127869368/319659860 bytes downloaded (40%), overall progress 40%
[0118/145935:INFO:delta_performer.cc(150)] Completed 507/1040 operations (48%), 166224312/319659860 bytes downloaded (52%), overall progress 50%

(update interrupted and resumed)

[0118/150058:INFO:delta_performer.cc(150)] Resuming after 582/1040 operations (55%), 195577374/319659860 bytes downloaded (61%), overall progress 57%
[0118/150058:INFO:delta_performer.cc(451)] Starting to apply update payload operations
...
[0118/150102:INFO:delta_performer.cc(150)] Completed 604/1040 operations (58%), 200934046/319659860 bytes downloaded (62%), overall progress 60%
[0118/150116:INFO:delta_performer.cc(150)] Completed 749/1040 operations (72%), 221543046/319659860 bytes downloaded (69%), overall progress 70%
[0118/150134:INFO:delta_performer.cc(150)] Completed 840/1040 operations (80%), 255736454/319659860 bytes downloaded (80%), overall progress 80%
[0118/150154:INFO:delta_performer.cc(150)] Completed 936/1040 operations (90%), 289225350/319659860 bytes downloaded (90%), overall progress 90%
[0118/150212:INFO:delta_performer.cc(150)] Completed 1040/1040 operations (100%), 319659860/319659860 bytes downloaded (100%), overall progress 100%

BUG=chromium-os:37910
TEST=Passes unit tests
TEST=Update works, progress logged as expected on x86-alex

Change-Id: I2ec5511fc20df05a264e59651528c65133209132
Reviewed-on: https://gerrit.chromium.org/gerrit/41301
Tested-by: Gilad Arnold <garnold@chromium.org>
Reviewed-by: Jay Srinivasan <jaysri@chromium.org>
Commit-Queue: Gilad Arnold <garnold@chromium.org>