Abort long-running benchmarks, report progress.

A typical storage device finishes the benchmark in under 10 seconds,
but some extremely slow devices can take minutes, resulting in a
confusing UX that looks like we've frozen.  Even worse, we keep
churning through all that I/O even though we know the device will
blow past our user-warning threshold.

So periodically check if we've timed out, and also use that to report
progress up into the Settings UI.

Test: manual
Bug: 62201209, 65639764, 67055204
Change-Id: I321397bcff230976f034cede0947d4a5a1f3e8a7

Benchmark.cpp

@@ -18,8 +18,10 @@
 #include "BenchmarkGen.h"
 #include "VolumeManager.h"
 
+#include <android-base/chrono_utils.h>
 #include <android-base/file.h>
 #include <android-base/logging.h>
+
 #include <cutils/iosched_policy.h>
 #include <hardware_legacy/power.h>
 #include <private/android_filesystem_config.h>
@@ -30,18 +32,65 @@
 #include <sys/resource.h>
 #include <unistd.h>
 
-#define ENABLE_DROP_CACHES 1
-
 using android::base::ReadFileToString;
 using android::base::WriteStringToFile;
 
 namespace android {
 namespace vold {
 
+// Benchmark currently uses chdir(), which means we can only
+// safely run one at a time.
+static std::mutex kBenchmarkLock;
+
 static const char* kWakeLock = "Benchmark";
 
+// Reasonable cards are able to complete the create/run stages
+// in under 20 seconds.
+constexpr auto kTimeout = 20s;
+
+// RAII class for boosting device performance during benchmarks.
+class PerformanceBoost {
+private:
+    int orig_prio;
+    int orig_ioprio;
+    IoSchedClass orig_clazz;
+
+public:
+    PerformanceBoost() {
+        errno = 0;
+        orig_prio = getpriority(PRIO_PROCESS, 0);
+        if (errno != 0) {
+            PLOG(WARNING) << "Failed to getpriority";
+            orig_prio = 0;
+        }
+        if (setpriority(PRIO_PROCESS, 0, -10) != 0) {
+            PLOG(WARNING) << "Failed to setpriority";
+        }
+        if (android_get_ioprio(0, &orig_clazz, &orig_ioprio)) {
+            PLOG(WARNING) << "Failed to android_get_ioprio";
+            orig_ioprio = 0;
+            orig_clazz = IoSchedClass_NONE;
+        }
+        if (android_set_ioprio(0, IoSchedClass_RT, 0)) {
+            PLOG(WARNING) << "Failed to android_set_ioprio";
+        }
+    }
+
+    ~PerformanceBoost() {
+        if (android_set_ioprio(0, orig_clazz, orig_ioprio)) {
+            PLOG(WARNING) << "Failed to android_set_ioprio";
+        }
+        if (setpriority(PRIO_PROCESS, 0, orig_prio) != 0) {
+            PLOG(WARNING) << "Failed to setpriority";
+        }
+    }
+};
+
 static status_t benchmarkInternal(const std::string& rootPath,
+        const android::sp<android::os::IVoldTaskListener>& listener,
         android::os::PersistableBundle* extras) {
+    status_t res = 0;
+
     auto path = rootPath;
     path += "/misc";
     if (android::vold::PrepareDir(path, 01771, AID_SYSTEM, AID_MISC)) {
@@ -56,28 +105,6 @@ static status_t benchmarkInternal(const std::string& rootPath,
         return -1;
     }
 
-    errno = 0;
-    int orig_prio = getpriority(PRIO_PROCESS, 0);
-    if (errno != 0) {
-        PLOG(ERROR) << "Failed to getpriority";
-        return -1;
-    }
-    if (setpriority(PRIO_PROCESS, 0, -10) != 0) {
-        PLOG(ERROR) << "Failed to setpriority";
-        return -1;
-    }
-
-    IoSchedClass orig_clazz = IoSchedClass_NONE;
-    int orig_ioprio = 0;
-    if (android_get_ioprio(0, &orig_clazz, &orig_ioprio)) {
-        PLOG(ERROR) << "Failed to android_get_ioprio";
-        return -1;
-    }
-    if (android_set_ioprio(0, IoSchedClass_RT, 0)) {
-        PLOG(ERROR) << "Failed to android_set_ioprio";
-        return -1;
-    }
-
     char orig_cwd[PATH_MAX];
     if (getcwd(orig_cwd, PATH_MAX) == NULL) {
         PLOG(ERROR) << "Failed getcwd";
@@ -90,66 +117,76 @@ static status_t benchmarkInternal(const std::string& rootPath,
 
     sync();
 
-    LOG(INFO) << "Benchmarking " << path;
+    extras->putString(String16("path"), String16(path.c_str()));
-    nsecs_t start = systemTime(SYSTEM_TIME_BOOTTIME);
+    extras->putString(String16("ident"), String16(BenchmarkIdent().c_str()));
 
-    BenchmarkCreate();
+    // Always create
-    sync();
+    {
-    nsecs_t create = systemTime(SYSTEM_TIME_BOOTTIME);
+        android::base::Timer timer;
-
+        LOG(INFO) << "Creating " << path;
-#if ENABLE_DROP_CACHES
+        res |= BenchmarkCreate([&](int progress) -> bool {
-    LOG(VERBOSE) << "Before drop_caches";
+            if (listener) {
-    if (!WriteStringToFile("3", "/proc/sys/vm/drop_caches")) {
+                listener->onStatus(progress, *extras);
-        PLOG(ERROR) << "Failed to drop_caches";
+            }
+            return (timer.duration() < kTimeout);
+        });
+        sync();
+        if (res == OK) extras->putLong(String16("create"), timer.duration().count());
     }
-    LOG(VERBOSE) << "After drop_caches";
-#endif
-    nsecs_t drop = systemTime(SYSTEM_TIME_BOOTTIME);
 
-    BenchmarkRun();
+    // Only drop when we haven't aborted
-    sync();
+    if (res == OK) {
-    nsecs_t run = systemTime(SYSTEM_TIME_BOOTTIME);
+        android::base::Timer timer;
+        LOG(VERBOSE) << "Before drop_caches";
+        if (!WriteStringToFile("3", "/proc/sys/vm/drop_caches")) {
+            PLOG(ERROR) << "Failed to drop_caches";
+            res = -1;
+        }
+        LOG(VERBOSE) << "After drop_caches";
+        sync();
+        if (res == OK) extras->putLong(String16("drop"), timer.duration().count());
+    }
 
-    BenchmarkDestroy();
+    // Only run when we haven't aborted
-    sync();
+    if (res == OK) {
-    nsecs_t destroy = systemTime(SYSTEM_TIME_BOOTTIME);
+        android::base::Timer timer;
+        LOG(INFO) << "Running " << path;
+        res |= BenchmarkRun([&](int progress) -> bool {
+            if (listener) {
+                listener->onStatus(progress, *extras);
+            }
+            return (timer.duration() < kTimeout);
+        });
+        sync();
+        if (res == OK) extras->putLong(String16("run"), timer.duration().count());
+    }
+
+    // Always destroy
+    {
+        android::base::Timer timer;
+        LOG(INFO) << "Destroying " << path;
+        res |= BenchmarkDestroy();
+        sync();
+        if (res == OK) extras->putLong(String16("destroy"), timer.duration().count());
+    }
 
     if (chdir(orig_cwd) != 0) {
         PLOG(ERROR) << "Failed to chdir";
-    }
+        return -1;
-    if (android_set_ioprio(0, orig_clazz, orig_ioprio)) {
-        PLOG(ERROR) << "Failed to android_set_ioprio";
-    }
-    if (setpriority(PRIO_PROCESS, 0, orig_prio) != 0) {
-        PLOG(ERROR) << "Failed to setpriority";
     }
 
-    nsecs_t create_d = create - start;
+    return res;
-    nsecs_t drop_d = drop - create;
-    nsecs_t run_d = run - drop;
-    nsecs_t destroy_d = destroy - run;
-
-    LOG(INFO) << "create took " << nanoseconds_to_milliseconds(create_d) << "ms";
-    LOG(INFO) << "drop took " << nanoseconds_to_milliseconds(drop_d) << "ms";
-    LOG(INFO) << "run took " << nanoseconds_to_milliseconds(run_d) << "ms";
-    LOG(INFO) << "destroy took " << nanoseconds_to_milliseconds(destroy_d) << "ms";
-
-    extras->putString(String16("path"), String16(path.c_str()));
-    extras->putString(String16("ident"), String16(BenchmarkIdent().c_str()));
-    extras->putLong(String16("create"), create_d);
-    extras->putLong(String16("drop"), drop_d);
-    extras->putLong(String16("run"), run_d);
-    extras->putLong(String16("destroy"), destroy_d);
-
-    return 0;
 }
 
 void Benchmark(const std::string& path,
         const android::sp<android::os::IVoldTaskListener>& listener) {
+    std::lock_guard<std::mutex> lock(kBenchmarkLock);
     acquire_wake_lock(PARTIAL_WAKE_LOCK, kWakeLock);
 
+    PerformanceBoost boost;
     android::os::PersistableBundle extras;
-    status_t res = benchmarkInternal(path, &extras);
+
+    status_t res = benchmarkInternal(path, listener, &extras);
     if (listener) {
         listener->onFinished(res, extras);
     }

bench/benchgen.py

@@ -157,6 +157,7 @@ with open("BenchmarkGen.h", 'w') as bench:
 #include <fcntl.h>
 
 #include <algorithm>
+#include <functional>
 #include <string>
 
 #include <Utils.h>
@@ -164,7 +165,8 @@ with open("BenchmarkGen.h", 'w') as bench:
 namespace android {
 namespace vold {
 
-static status_t BenchmarkRun() {
+static status_t BenchmarkRun(std::function<bool(int)> checkpoint) {
+
 """
 
     print >>bench, "char* buf = (char*) malloc(%d);" % (bufsize)
@@ -175,13 +177,19 @@ static status_t BenchmarkRun() {
     events = sorted(events, key=lambda e: e.time)
     active = set()
     defined = set()
+    i = 0
+    total = len(events)
     for e in events:
+        i += 1
+        if i % 256 == 0:
+            print >>bench, "if (!checkpoint(%d)) return -1;" % (50 + ((i * 50) / total))
+
         if e.call == "openat":
             fd, f, handle = extract_file(e, e.ret)
             if f:
                 active.add(handle)
                 if handle not in defined:
-                    print >>bench, "int ",
+                    print >>bench, "int",
                     defined.add(handle)
                 create_mode = ''
                 if 'O_CREAT' in e.args[2]:
@@ -297,11 +305,17 @@ static status_t CreateFile(const char* name, int len) {
     return OK;
 }
 
-static status_t BenchmarkCreate() {
+static status_t BenchmarkCreate(std::function<bool(int)> checkpoint) {
 status_t res = 0;
 res |= CreateFile("stub", 0);
 """
+    i = 0
+    total = len(files.values())
     for f in files.values():
+        i += 1
+        if i % 12 == 0:
+            print >>bench, "if (!checkpoint(%d)) return -1;" % ((i * 50) / total)
+
         print >>bench, 'res |= CreateFile("file%s", %d);' % (f.ident, f.size)
 
     print >>bench, """