Add time and I/O info to last_install

One example of last_install is:

/sideload/package.zip
1
time_total: 101
bytes_written_system: 14574000
bytes_stashed_system: 100
bytes_written_vendor: 5107400
bytes_stashed_vendor: 0

Bug: 28658632
Change-Id: I4bf79ea71a609068d38fbce6b41bcb892524aa7a

install.cpp

@@ -24,6 +24,7 @@
 #include <unistd.h>
 
 #include <chrono>
+#include <string>
 #include <vector>
 
 #include "common.h"
@@ -50,7 +51,9 @@ static const float DEFAULT_IMAGE_PROGRESS_FRACTION = 0.1;
 
 // If the package contains an update binary, extract it and run it.
 static int
-try_update_binary(const char* path, ZipArchive* zip, bool* wipe_cache) {
+try_update_binary(const char* path, ZipArchive* zip, bool* wipe_cache,
+                  std::vector<std::string>& log_buffer)
+{
     const ZipEntry* binary_entry =
             mzFindZipEntry(zip, ASSUMED_UPDATE_BINARY_NAME);
     if (binary_entry == NULL) {
@@ -183,6 +186,10 @@ try_update_binary(const char* path, ZipArchive* zip, bool* wipe_cache) {
             ui->SetEnableReboot(true);
         } else if (strcmp(command, "retry_update") == 0) {
             retry_update = true;
+        } else if (strcmp(command, "log") == 0) {
+            // Save the logging request from updater and write to
+            // last_install later.
+            log_buffer.push_back(std::string(strtok(NULL, "\n")));
         } else {
             LOGE("unknown command [%s]\n", command);
         }
@@ -203,7 +210,8 @@ try_update_binary(const char* path, ZipArchive* zip, bool* wipe_cache) {
 }
 
 static int
-really_install_package(const char *path, bool* wipe_cache, bool needs_mount)
+really_install_package(const char *path, bool* wipe_cache, bool needs_mount,
+                       std::vector<std::string>& log_buffer)
 {
     ui->SetBackground(RecoveryUI::INSTALLING_UPDATE);
     ui->Print("Finding update package...\n");
@@ -261,7 +269,7 @@ really_install_package(const char *path, bool* wipe_cache, bool needs_mount)
     // Verify and install the contents of the package.
     ui->Print("Installing update...\n");
     ui->SetEnableReboot(false);
-    int result = try_update_binary(path, &zip, wipe_cache);
+    int result = try_update_binary(path, &zip, wipe_cache, log_buffer);
     ui->SetEnableReboot(true);
     ui->Print("\n");
 
@@ -275,6 +283,7 @@ install_package(const char* path, bool* wipe_cache, const char* install_file,
                 bool needs_mount)
 {
     modified_flash = true;
+    auto start = std::chrono::system_clock::now();
 
     FILE* install_log = fopen_path(install_file, "w");
     if (install_log) {
@@ -284,15 +293,25 @@ install_package(const char* path, bool* wipe_cache, const char* install_file,
         LOGE("failed to open last_install: %s\n", strerror(errno));
     }
     int result;
+    std::vector<std::string> log_buffer;
     if (setup_install_mounts() != 0) {
         LOGE("failed to set up expected mounts for install; aborting\n");
         result = INSTALL_ERROR;
     } else {
-        result = really_install_package(path, wipe_cache, needs_mount);
+        result = really_install_package(path, wipe_cache, needs_mount, log_buffer);
     }
     if (install_log) {
         fputc(result == INSTALL_SUCCESS ? '1' : '0', install_log);
         fputc('\n', install_log);
+        std::chrono::duration<double> duration = std::chrono::system_clock::now() - start;
+        int count = static_cast<int>(duration.count());
+        // Report the time spent to apply OTA update in seconds.
+        fprintf(install_log, "time_total: %d\n", count);
+
+        for (const auto& s : log_buffer) {
+            fprintf(install_log, "%s\n", s.c_str());
+        }
+
         fclose(install_log);
     }
     return result;

updater/blockimg.cpp

@@ -373,6 +373,7 @@ struct CommandParameters {
     bool isunresumable;
     int version;
     size_t written;
+    size_t stashed;
     NewThreadInfo nti;
     pthread_t thread;
     std::vector<uint8_t> buffer;
@@ -777,6 +778,7 @@ static int SaveStash(CommandParameters& params, const std::string& base,
     }
 
     fprintf(stderr, "stashing %zu blocks to %s\n", blocks, id.c_str());
+    params.stashed += blocks;
     return WriteStash(base, id, blocks, buffer, false, nullptr);
 }
 
@@ -973,6 +975,7 @@ static int LoadSrcTgtVersion3(CommandParameters& params, RangeSet& tgt, size_t&
                 return -1;
             }
 
+            params.stashed += src_blocks;
             // Can be deleted when the write has completed
             if (!stash_exists) {
                 params.freestash = srchash;
@@ -1517,8 +1520,17 @@ static Value* PerformBlockImageUpdate(const char* name, State* state, int /* arg
         pthread_join(params.thread, nullptr);
 
         fprintf(stderr, "wrote %zu blocks; expected %d\n", params.written, total_blocks);
+        fprintf(stderr, "stashed %zu blocks\n", params.stashed);
         fprintf(stderr, "max alloc needed was %zu\n", params.buffer.size());
 
+        const char* partition = strrchr(blockdev_filename->data, '/');
+        if (partition != nullptr && *(partition+1) != 0) {
+            fprintf(cmd_pipe, "log bytes_written_%s: %zu\n", partition + 1,
+                    params.written * BLOCKSIZE);
+            fprintf(cmd_pipe, "log bytes_stashed_%s: %zu\n", partition + 1,
+                    params.stashed * BLOCKSIZE);
+            fflush(cmd_pipe);
+        }
         // Delete stash only after successfully completing the update, as it
         // may contain blocks needed to complete the update later.
         DeleteStash(params.stashbase);