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>
2 files changed