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>
diff --git a/delta_performer.h b/delta_performer.h
index 2010765..8370b81 100644
--- a/delta_performer.h
+++ b/delta_performer.h
@@ -9,6 +9,7 @@
#include <vector>
+#include <base/time.h>
#include <google/protobuf/repeated_field.h>
#include <gtest/gtest_prod.h> // for FRIEND_TEST
@@ -37,6 +38,19 @@
static const uint64_t kDeltaManifestSizeSize;
static const char kUpdatePayloadPublicKeyPath[];
+ // Defines the granularity of progress logging in terms of how many "completed
+ // chunks" we want to report at the most.
+ static const unsigned kProgressLogMaxChunks;
+ // Defines a timeout since the last progress was logged after which we want to
+ // force another log message (even if the current chunk was not completed).
+ static const unsigned kProgressLogTimeoutSeconds;
+ // These define the relative weights (0-100) we give to the different work
+ // components associated with an update when computing an overall progress.
+ // Currently they include the download progress and the number of completed
+ // operations. They must add up to one hundred (100).
+ static const unsigned kProgressDownloadWeight;
+ static const unsigned kProgressOperationsWeight;
+
DeltaPerformer(PrefsInterface* prefs,
SystemState* system_state,
InstallPlan* install_plan)
@@ -51,7 +65,14 @@
buffer_offset_(0),
last_updated_buffer_offset_(kuint64max),
block_size_(0),
- public_key_path_(kUpdatePayloadPublicKeyPath) {}
+ public_key_path_(kUpdatePayloadPublicKeyPath),
+ total_bytes_received_(0),
+ num_rootfs_operations_(0),
+ num_total_operations_(0),
+ overall_progress_(0),
+ last_progress_chunk_(0),
+ forced_progress_log_wait_(
+ base::TimeDelta::FromSeconds(kProgressLogTimeoutSeconds)) {}
// Opens the kernel. Should be called before or after Open(), but before
// Write(). The kernel file will be close()d when Close() is called.
@@ -152,6 +173,12 @@
friend class DeltaPerformerTest;
FRIEND_TEST(DeltaPerformerTest, IsIdempotentOperationTest);
+ // Logs the progress of downloading/applying an update.
+ void LogProgress(const char* message_prefix);
+
+ // Update overall progress metrics, log as necessary.
+ void UpdateOverallProgress(bool force_log, const char* message_prefix);
+
static bool IsIdempotentOperation(
const DeltaArchiveManifest_InstallOperation& op);
@@ -170,7 +197,7 @@
// matches what's specified in the manifest in the payload.
// Returns kActionCodeSuccess on match or a suitable error code otherwise.
ActionExitCode ValidateOperationHash(
- const DeltaArchiveManifest_InstallOperation& operation, bool should_log);
+ const DeltaArchiveManifest_InstallOperation& operation);
// Interprets the given |protobuf| as a DeltaArchiveManifest protocol buffer
// of the given protobuf_length and verifies that the signed hash of the
@@ -242,7 +269,7 @@
uint64_t manifest_metadata_size_;
// Index of the next operation to perform in the manifest.
- int next_operation_num_;
+ size_t next_operation_num_;
// buffer_ is a window of the data that's been downloaded. At first,
// it contains the beginning of the download, but after the protobuf
@@ -271,6 +298,25 @@
// override with test keys.
std::string public_key_path_;
+ // The number of bytes received so far, used for progress tracking.
+ size_t total_bytes_received_;
+
+ // The number rootfs and total operations in a payload, once we know them.
+ size_t num_rootfs_operations_;
+ size_t num_total_operations_;
+
+ // An overall progress counter, which should reflect both download progress
+ // and the ratio of applied operations. Range is 0-100.
+ unsigned overall_progress_;
+
+ // The last progress chunk recorded.
+ unsigned last_progress_chunk_;
+
+ // The timeout after which we should force emitting a progress log (constant),
+ // and the actual point in time for the next forced log to be emitted.
+ const base::TimeDelta forced_progress_log_wait_;
+ base::Time forced_progress_log_time_;
+
DISALLOW_COPY_AND_ASSIGN(DeltaPerformer);
};