Faster bugreports (2/n)

- Having a system property to disable parallel run function.
- Post 'DumpTraces' to the thread pool. 3% is
  improved compared with single thread run.

Bug: 136262402
Test: atest dumpstate_test
Test: atest dumpstate_smoke_test
Test: Manual enable and disable parallel run
Test: Manual trigger report using hardware key
Test: Manual trigger using bugreport shortcut
Change-Id: I2185cc3e2f429a150605d6268324c52d137db385
Merged-In: I2185cc3e2f429a150605d6268324c52d137db385
(cherry picked from commit 5377d797fff94e0e070fdbbadc89288d90cc5f2c)
diff --git a/cmds/dumpstate/DumpPool.cpp b/cmds/dumpstate/DumpPool.cpp
index 7324ead..e174c8e 100644
--- a/cmds/dumpstate/DumpPool.cpp
+++ b/cmds/dumpstate/DumpPool.cpp
@@ -33,7 +33,8 @@
 
 const std::string DumpPool::PREFIX_TMPFILE_NAME = "dump-tmp.";
 
-DumpPool::DumpPool(const std::string& tmp_root) : tmp_root_(tmp_root), shutdown_(false) {
+DumpPool::DumpPool(const std::string& tmp_root) : tmp_root_(tmp_root), shutdown_(false),
+        log_duration_(true) {
     assert(!tmp_root.empty());
     deleteTempFiles(tmp_root_);
 }
@@ -99,6 +100,26 @@
     }
 }
 
+void DumpPool::setLogDuration(bool log_duration) {
+    log_duration_ = log_duration;
+}
+
+template <>
+void DumpPool::invokeTask<std::function<void()>>(std::function<void()> dump_func,
+        const std::string& duration_title, int out_fd) {
+    DurationReporter duration_reporter(duration_title, /*logcat_only =*/!log_duration_,
+            /*verbose =*/false, out_fd);
+    std::invoke(dump_func);
+}
+
+template <>
+void DumpPool::invokeTask<std::function<void(int)>>(std::function<void(int)> dump_func,
+        const std::string& duration_title, int out_fd) {
+    DurationReporter duration_reporter(duration_title, /*logcat_only =*/!log_duration_,
+            /*verbose =*/false, out_fd);
+    std::invoke(dump_func, out_fd);
+}
+
 std::unique_ptr<DumpPool::TmpFile> DumpPool::createTempFile() {
     auto tmp_file_ptr = std::make_unique<TmpFile>();
     std::string file_name_format = "%s/" + PREFIX_TMPFILE_NAME + "XXXXXX";
diff --git a/cmds/dumpstate/DumpPool.h b/cmds/dumpstate/DumpPool.h
index 266d519..a4ea875 100644
--- a/cmds/dumpstate/DumpPool.h
+++ b/cmds/dumpstate/DumpPool.h
@@ -29,26 +29,32 @@
 namespace os {
 namespace dumpstate {
 
+class DumpPoolTest;
+
 /*
  * A thread pool with the fixed number of threads to execute multiple dump tasks
- * simultaneously for the dumpstate. The dump task is a callable function
- * included a file descriptor as a parameter, and the task could dump results to
- * that fd. For example:
+ * simultaneously for the dumpstate. The dump task is a callable function. It
+ * could include a file descriptor as a parameter to redirect dump results, if
+ * it needs to output results to the bugreport. This can avoid messing up
+ * bugreport's results when multiple dump tasks are running at the same time.
+ * Takes an example below for the usage of the DumpPool:
  *
- * void DumpXXXX(int out_fd) {
+ * void DumpFoo(int out_fd) {
  *     dprintf(out_fd, "Dump result to out_fd ...");
  * }
  * ...
  * DumpPool pool(tmp_root);
- * pool.enqueueTask("TaskName", &DumpXXXX, std::placeholders::_1);
+ * pool.enqueueTaskWithFd("TaskName", &DumpFoo, std::placeholders::_1);
  * ...
  * pool.waitForTask("TaskName");
  *
- * DumpXXXX is a callable function included a out_fd parameter. Using the
- * enqueueTask method in DumpPool to enqueue the task to the pool. The
- * std::placeholders::_1 is placeholder for DumpPool to pass a fd argument.
+ * DumpFoo is a callable function included a out_fd parameter. Using the
+ * enqueueTaskWithFd method in DumpPool to enqueue the task to the pool. The
+ * std::placeholders::_1 is a placeholder for DumpPool to pass a fd argument.
  */
 class DumpPool {
+  friend class android::os::dumpstate::DumpPoolTest;
+
   public:
     /*
      * Creates a thread pool.
@@ -72,17 +78,40 @@
     void shutdown();
 
     /*
-     * Adds a task with a task name into the queue of the thread pool.
+     * Adds a task into the queue of the thread pool.
      *
-     * |task_name| The name of the task.
-     * |f| Callable function to execute the task. This function must
-     *     include a parameter of file descriptor to output dump result.
+     * |task_name| The name of the task. It's also the title of the
+     * DurationReporter log.
+     * |f| Callable function to execute the task.
      * |args| A list of arguments.
+     *
+     * TODO(b/164369078): remove this api to have just one enqueueTask for consistency.
      */
-    template<class F, class... Args> void enqueueTask(const std::string& task_name,
-            F&& f, Args&&... args) {
-        auto func = std::bind(std::forward<F>(f), std::forward<Args>(args)...);
-        futures_map_[task_name] = post(func);
+    template<class F, class... Args> void enqueueTask(const std::string& task_name, F&& f,
+            Args&&... args) {
+        std::function<void(void)> func = std::bind(std::forward<F>(f),
+                std::forward<Args>(args)...);
+        futures_map_[task_name] = post(task_name, func);
+        if (threads_.empty()) {
+            start();
+        }
+    }
+
+    /*
+     * Adds a task into the queue of the thread pool. The task takes a file
+     * descriptor as a parameter to redirect dump results to a temporary file.
+     *
+     * |task_name| The name of the task. It's also the title of the
+     * DurationReporter log.
+     * |f| Callable function to execute the task.
+     * |args| A list of arguments. A placeholder std::placeholders::_1 as a fd
+     * argument needs to be included here.
+     */
+    template<class F, class... Args> void enqueueTaskWithFd(const std::string& task_name, F&& f,
+            Args&&... args) {
+        std::function<void(int)> func = std::bind(std::forward<F>(f),
+                std::forward<Args>(args)...);
+        futures_map_[task_name] = post(task_name, func);
         if (threads_.empty()) {
             start();
         }
@@ -111,13 +140,15 @@
     using Task = std::packaged_task<std::string()>;
     using Future = std::shared_future<std::string>;
 
-    template<class T> Future post(T dump_func) {
+    template<class T> void invokeTask(T dump_func, const std::string& duration_title, int out_fd);
+
+    template<class T> Future post(const std::string& task_name, T dump_func) {
         Task packaged_task([=]() {
             std::unique_ptr<TmpFile> tmp_file_ptr = createTempFile();
             if (!tmp_file_ptr) {
                 return std::string("");
             }
-            std::invoke(dump_func, tmp_file_ptr->fd.get());
+            invokeTask(dump_func, task_name, tmp_file_ptr->fd.get());
             fsync(tmp_file_ptr->fd.get());
             return std::string(tmp_file_ptr->path);
         });
@@ -138,12 +169,21 @@
     void setThreadName(const pthread_t thread, int id);
     void loop();
 
+    /*
+     * For test purpose only. Enables or disables logging duration of the task.
+     *
+     * |log_duration| if true, DurationReporter is initiated to log duration of
+     * the task.
+     */
+    void setLogDuration(bool log_duration);
+
   private:
     static const int MAX_THREAD_COUNT = 4;
 
     /* A path to a temporary folder for threads to create temporary files. */
     std::string tmp_root_;
     bool shutdown_;
+    bool log_duration_; // For test purpose only, the default value is true.
     std::mutex lock_;  // A lock for the tasks_.
     std::condition_variable condition_variable_;
 
diff --git a/cmds/dumpstate/DumpstateUtil.cpp b/cmds/dumpstate/DumpstateUtil.cpp
index 4b69607..eeaa5a3 100644
--- a/cmds/dumpstate/DumpstateUtil.cpp
+++ b/cmds/dumpstate/DumpstateUtil.cpp
@@ -180,6 +180,7 @@
 std::string PropertiesHelper::build_type_ = "";
 int PropertiesHelper::dry_run_ = -1;
 int PropertiesHelper::unroot_ = -1;
+int PropertiesHelper::parallel_run_ = -1;
 
 bool PropertiesHelper::IsUserBuild() {
     if (build_type_.empty()) {
@@ -202,6 +203,14 @@
     return unroot_ == 1;
 }
 
+bool PropertiesHelper::IsParallelRun() {
+    if (parallel_run_ == -1) {
+        parallel_run_ = android::base::GetBoolProperty("dumpstate.parallel_run",
+                /* default_value = */true) ? 1 : 0;
+    }
+    return parallel_run_ == 1;
+}
+
 int DumpFileToFd(int out_fd, const std::string& title, const std::string& path) {
     android::base::unique_fd fd(TEMP_FAILURE_RETRY(open(path.c_str(), O_RDONLY | O_NONBLOCK | O_CLOEXEC)));
     if (fd.get() < 0) {
diff --git a/cmds/dumpstate/DumpstateUtil.h b/cmds/dumpstate/DumpstateUtil.h
index b7ac25c..b099443 100644
--- a/cmds/dumpstate/DumpstateUtil.h
+++ b/cmds/dumpstate/DumpstateUtil.h
@@ -176,10 +176,18 @@
      */
     static bool IsUnroot();
 
+    /*
+     * Whether or not the parallel run is enabled. Setting the system property
+     * 'dumpstate.parallel_run' to false to disable it, otherwise it returns
+     * true by default.
+     */
+    static bool IsParallelRun();
+
   private:
     static std::string build_type_;
     static int dry_run_;
     static int unroot_;
+    static int parallel_run_;
 };
 
 /*
diff --git a/cmds/dumpstate/dumpstate.cpp b/cmds/dumpstate/dumpstate.cpp
index 84de9f3..472a0f1 100644
--- a/cmds/dumpstate/dumpstate.cpp
+++ b/cmds/dumpstate/dumpstate.cpp
@@ -95,6 +95,7 @@
 using ::android::hardware::dumpstate::V1_1::toString;
 using ::std::literals::chrono_literals::operator""ms;
 using ::std::literals::chrono_literals::operator""s;
+using ::std::placeholders::_1;
 
 // TODO: remove once moved to namespace
 using android::defaultServiceManager;
@@ -113,6 +114,7 @@
 using android::os::IDumpstateListener;
 using android::os::dumpstate::CommandOptions;
 using android::os::dumpstate::DumpFileToFd;
+using android::os::dumpstate::DumpPool;
 using android::os::dumpstate::PropertiesHelper;
 
 // Keep in sync with
@@ -196,8 +198,26 @@
     func_ptr(__VA_ARGS__);                                  \
     RETURN_IF_USER_DENIED_CONSENT();
 
+// Runs func_ptr, and logs a duration report after it's finished.
+#define RUN_SLOW_FUNCTION_AND_LOG(log_title, func_ptr, ...)      \
+    {                                                            \
+        DurationReporter duration_reporter_in_macro(log_title);  \
+        func_ptr(__VA_ARGS__);                                   \
+    }
+
+// Similar with RUN_SLOW_FUNCTION_WITH_CONSENT_CHECK, an additional duration report
+// is output after a slow function is finished.
+#define RUN_SLOW_FUNCTION_WITH_CONSENT_CHECK_AND_LOG(log_title, func_ptr, ...) \
+    RETURN_IF_USER_DENIED_CONSENT();                                           \
+    RUN_SLOW_FUNCTION_AND_LOG(log_title, func_ptr, __VA_ARGS__);               \
+    RETURN_IF_USER_DENIED_CONSENT();
+
 static const char* WAKE_LOCK_NAME = "dumpstate_wakelock";
 
+// Names of parallel tasks, they are used for the DumpPool to identify the dump
+// task and the log title of the duration report.
+static const std::string DUMP_TRACES_TASK = "DUMP TRACES";
+
 namespace android {
 namespace os {
 namespace {
@@ -762,8 +782,9 @@
     RunCommandToFd(STDOUT_FILENO, "", {"uptime", "-p"},
                    CommandOptions::WithTimeout(1).Always().Build());
     printf("Bugreport format version: %s\n", version_.c_str());
-    printf("Dumpstate info: id=%d pid=%d dry_run=%d args=%s bugreport_mode=%s\n", id_, pid_,
-           PropertiesHelper::IsDryRun(), options_->args.c_str(), options_->bugreport_mode.c_str());
+    printf("Dumpstate info: id=%d pid=%d dry_run=%d parallel_run=%d args=%s bugreport_mode=%s\n",
+           id_, pid_, PropertiesHelper::IsDryRun(), PropertiesHelper::IsParallelRun(),
+           options_->args.c_str(), options_->bugreport_mode.c_str());
     printf("\n");
 }
 
@@ -1682,7 +1703,18 @@
     time_t logcat_ts = time(nullptr);
 
     /* collect stack traces from Dalvik and native processes (needs root) */
-    RUN_SLOW_FUNCTION_WITH_CONSENT_CHECK(ds.DumpTraces, &dump_traces_path);
+    if (dump_pool_) {
+        RETURN_IF_USER_DENIED_CONSENT();
+        // One thread is enough since we only need to enqueue DumpTraces here.
+        dump_pool_->start(/* thread_counts = */1);
+
+        // DumpTraces takes long time, post it to the another thread in the
+        // pool, if pool is available
+        dump_pool_->enqueueTask(DUMP_TRACES_TASK, &Dumpstate::DumpTraces, &ds, &dump_traces_path);
+    } else {
+        RUN_SLOW_FUNCTION_WITH_CONSENT_CHECK_AND_LOG(DUMP_TRACES_TASK, ds.DumpTraces,
+                &dump_traces_path);
+    }
 
     /* Run some operations that require root. */
     ds.tombstone_data_ = GetDumpFds(TOMBSTONE_DIR, TOMBSTONE_FILE_PREFIX, !ds.IsZipping());
@@ -1725,6 +1757,15 @@
     DumpFile("PSI memory", "/proc/pressure/memory");
     DumpFile("PSI io", "/proc/pressure/io");
 
+    if (dump_pool_) {
+        RETURN_IF_USER_DENIED_CONSENT();
+        dump_pool_->waitForTask(DUMP_TRACES_TASK);
+
+        // Current running thread in the pool is the root user also. Shutdown
+        // the pool and restart later to ensure all threads in the pool could
+        // drop the root user.
+        dump_pool_->shutdown();
+    }
     if (!DropRootUser()) {
         return Dumpstate::RunStatus::ERROR;
     }
@@ -1883,8 +1924,6 @@
 }
 
 Dumpstate::RunStatus Dumpstate::DumpTraces(const char** path) {
-    DurationReporter duration_reporter("DUMP TRACES");
-
     const std::string temp_file_pattern = "/data/anr/dumptrace_XXXXXX";
     const size_t buf_size = temp_file_pattern.length() + 1;
     std::unique_ptr<char[]> file_name_buf(new char[buf_size]);
@@ -2556,6 +2595,7 @@
  */
 Dumpstate::RunStatus Dumpstate::RunInternal(int32_t calling_uid,
                                             const std::string& calling_package) {
+    DurationReporter duration_reporter("RUN INTERNAL", /* logcat_only = */true);
     LogDumpOptions(*options_);
     if (!options_->ValidateOptions()) {
         MYLOGE("Invalid options specified\n");
@@ -2717,6 +2757,13 @@
     // Don't buffer stdout
     setvbuf(stdout, nullptr, _IONBF, 0);
 
+    // Enable the parallel run if the client requests to output to a file.
+    EnableParallelRunIfNeeded();
+    // Using scope guard to make sure the dump pool can be shut down correctly.
+    auto scope_guard_to_shutdown_pool = android::base::make_scope_guard([=]() {
+        ShutdownDumpPool();
+    });
+
     // NOTE: there should be no stdout output until now, otherwise it would break the header.
     // In particular, DurationReport objects should be created passing 'title, NULL', so their
     // duration is logged into MYLOG instead.
@@ -2883,6 +2930,23 @@
     android::os::UnlinkAndLogOnError(path_);
 }
 
+void Dumpstate::EnableParallelRunIfNeeded() {
+    // The thread pool needs to create temporary files to receive dump results.
+    // That's why we only enable it when the bugreport client chooses to output
+    // to a file.
+    if (!PropertiesHelper::IsParallelRun() || !options_->OutputToFile()) {
+        return;
+    }
+    dump_pool_ = std::make_unique<DumpPool>(bugreport_internal_dir_);
+}
+
+void Dumpstate::ShutdownDumpPool() {
+    if (dump_pool_) {
+        dump_pool_->shutdown();
+        dump_pool_ = nullptr;
+    }
+}
+
 Dumpstate::RunStatus Dumpstate::HandleUserConsentDenied() {
     MYLOGD("User denied consent; deleting files and returning\n");
     CleanupTmpFiles();
@@ -3001,8 +3065,9 @@
     return singleton_;
 }
 
-DurationReporter::DurationReporter(const std::string& title, bool logcat_only, bool verbose)
-    : title_(title), logcat_only_(logcat_only), verbose_(verbose) {
+DurationReporter::DurationReporter(const std::string& title, bool logcat_only, bool verbose,
+        int duration_fd) : title_(title), logcat_only_(logcat_only), verbose_(verbose),
+        duration_fd_(duration_fd) {
     if (!title_.empty()) {
         started_ = Nanotime();
     }
@@ -3016,7 +3081,8 @@
         }
         if (!logcat_only_) {
             // Use "Yoda grammar" to make it easier to grep|sort sections.
-            printf("------ %.3fs was the duration of '%s' ------\n", elapsed, title_.c_str());
+            dprintf(duration_fd_, "------ %.3fs was the duration of '%s' ------\n",
+                    elapsed, title_.c_str());
         }
     }
 }
diff --git a/cmds/dumpstate/dumpstate.h b/cmds/dumpstate/dumpstate.h
index 0d25d30..d400dc7 100644
--- a/cmds/dumpstate/dumpstate.h
+++ b/cmds/dumpstate/dumpstate.h
@@ -35,6 +35,7 @@
 #include <ziparchive/zip_writer.h>
 
 #include "DumpstateUtil.h"
+#include "DumpPool.h"
 
 // Workaround for const char *args[MAX_ARGS_ARRAY_SIZE] variables until they're converted to
 // std::vector<std::string>
@@ -75,7 +76,7 @@
 class DurationReporter {
   public:
     explicit DurationReporter(const std::string& title, bool logcat_only = false,
-                              bool verbose = false);
+                              bool verbose = false, int duration_fd = STDOUT_FILENO);
 
     ~DurationReporter();
 
@@ -84,6 +85,7 @@
     bool logcat_only_;
     bool verbose_;
     uint64_t started_;
+    int duration_fd_;
 
     DISALLOW_COPY_AND_ASSIGN(DurationReporter);
 };
@@ -193,7 +195,7 @@
  * that are spread accross utils.cpp and dumpstate.cpp will be moved to it.
  */
 class Dumpstate {
-    friend class DumpstateTest;
+    friend class android::os::dumpstate::DumpstateTest;
 
   public:
     enum RunStatus { OK, HELP, INVALID_INPUT, ERROR, USER_CONSENT_DENIED, USER_CONSENT_TIMED_OUT };
@@ -490,6 +492,9 @@
     // List of open ANR dump files.
     std::vector<DumpData> anr_data_;
 
+    // A thread pool to execute dump tasks simultaneously if the parallel run is enabled.
+    std::unique_ptr<android::os::dumpstate::DumpPool> dump_pool_;
+
     // A callback to IncidentCompanion service, which checks user consent for sharing the
     // bugreport with the calling app. If the user has not responded yet to the dialog it will
     // be neither confirmed nor denied.
@@ -528,6 +533,10 @@
     // but leaves the log file alone.
     void CleanupTmpFiles();
 
+    // Create the thread pool to enable the parallel run function.
+    void EnableParallelRunIfNeeded();
+    void ShutdownDumpPool();
+
     RunStatus HandleUserConsentDenied();
 
     // Copies bugreport artifacts over to the caller's directories provided there is user consent or
diff --git a/cmds/dumpstate/tests/dumpstate_test.cpp b/cmds/dumpstate/tests/dumpstate_test.cpp
index d0a4826..b3cb434 100644
--- a/cmds/dumpstate/tests/dumpstate_test.cpp
+++ b/cmds/dumpstate/tests/dumpstate_test.cpp
@@ -97,6 +97,10 @@
         PropertiesHelper::unroot_ = unroot;
     }
 
+    void SetParallelRun(bool parallel_run) const {
+        PropertiesHelper::parallel_run_ = parallel_run;
+    }
+
     bool IsStandalone() const {
         return calls_ == 1;
     }
@@ -544,6 +548,10 @@
         ds.options_.reset(new Dumpstate::DumpOptions());
     }
 
+    void TearDown() {
+        ds.ShutdownDumpPool();
+    }
+
     // Runs a command and capture `stdout` and `stderr`.
     int RunCommand(const std::string& title, const std::vector<std::string>& full_command,
                    const CommandOptions& options = CommandOptions::DEFAULT) {
@@ -571,6 +579,10 @@
         ds.progress_.reset(new Progress(initial_max, progress, 1.2));
     }
 
+    void EnableParallelRunIfNeeded() {
+        ds.EnableParallelRunIfNeeded();
+    }
+
     std::string GetProgressMessage(int progress, int max,
             int old_max = 0, bool update_progress = true) {
         EXPECT_EQ(progress, ds.progress_->Get()) << "invalid progress";
@@ -1009,6 +1021,27 @@
     ds.listener_.clear();
 }
 
+TEST_F(DumpstateTest, DumpPool_withOutputToFileAndParallelRunEnabled_notNull) {
+    ds.options_->use_socket = false;
+    SetParallelRun(true);
+    EnableParallelRunIfNeeded();
+    EXPECT_TRUE(ds.options_->OutputToFile());
+    EXPECT_TRUE(ds.dump_pool_);
+}
+
+TEST_F(DumpstateTest, DumpPool_withNotOutputToFile_isNull) {
+    ds.options_->use_socket = true;
+    EnableParallelRunIfNeeded();
+    EXPECT_FALSE(ds.options_->OutputToFile());
+    EXPECT_FALSE(ds.dump_pool_);
+}
+
+TEST_F(DumpstateTest, DumpPool_withParallelRunDisabled_isNull) {
+    SetParallelRun(false);
+    EnableParallelRunIfNeeded();
+    EXPECT_FALSE(ds.dump_pool_);
+}
+
 class DumpstateServiceTest : public DumpstateBaseTest {
   public:
     DumpstateService dss;
@@ -1623,6 +1656,7 @@
 class DumpPoolTest : public DumpstateBaseTest {
   public:
     void SetUp() {
+        dump_pool_ = std::make_unique<DumpPool>(kTestDataPath);
         DumpstateBaseTest::SetUp();
         CreateOutputFile();
     }
@@ -1662,12 +1696,16 @@
         return count;
     }
 
+    void setLogDuration(bool log_duration) {
+        dump_pool_->setLogDuration(log_duration);
+    }
+
+    std::unique_ptr<DumpPool> dump_pool_;
     android::base::unique_fd out_fd_;
     std::string out_path_;
 };
 
-TEST_F(DumpPoolTest, EnqueueTask) {
-    DumpPool pool(kTestDataPath);
+TEST_F(DumpPoolTest, EnqueueTaskWithFd) {
     auto dump_func_1 = [](int out_fd) {
         dprintf(out_fd, "A");
     };
@@ -1678,19 +1716,37 @@
     auto dump_func_3 = [](int out_fd) {
         dprintf(out_fd, "C");
     };
-    pool.enqueueTask(/* task_name = */"1", dump_func_1, std::placeholders::_1);
-    pool.enqueueTask(/* task_name = */"2", dump_func_2, std::placeholders::_1);
-    pool.enqueueTask(/* task_name = */"3", dump_func_3, std::placeholders::_1);
+    setLogDuration(/* log_duration = */false);
+    dump_pool_->enqueueTaskWithFd(/* task_name = */"1", dump_func_1, std::placeholders::_1);
+    dump_pool_->enqueueTaskWithFd(/* task_name = */"2", dump_func_2, std::placeholders::_1);
+    dump_pool_->enqueueTaskWithFd(/* task_name = */"3", dump_func_3, std::placeholders::_1);
 
-    pool.waitForTask("1", "", out_fd_.get());
-    pool.waitForTask("2", "", out_fd_.get());
-    pool.waitForTask("3", "", out_fd_.get());
+    dump_pool_->waitForTask("1", "", out_fd_.get());
+    dump_pool_->waitForTask("2", "", out_fd_.get());
+    dump_pool_->waitForTask("3", "", out_fd_.get());
+    dump_pool_->shutdown();
 
     std::string result;
     ReadFileToString(out_path_, &result);
     EXPECT_THAT(result, StrEq("A\nB\nC\n"));
     EXPECT_THAT(getTempFileCounts(kTestDataPath), Eq(0));
-    pool.shutdown();
+}
+
+TEST_F(DumpPoolTest, EnqueueTask_withDurationLog) {
+    bool run_1 = false;
+    auto dump_func_1 = [&]() {
+        run_1 = true;
+    };
+
+    dump_pool_->enqueueTask(/* task_name = */"1", dump_func_1);
+    dump_pool_->waitForTask("1", "", out_fd_.get());
+    dump_pool_->shutdown();
+
+    std::string result;
+    ReadFileToString(out_path_, &result);
+    EXPECT_TRUE(run_1);
+    EXPECT_THAT(result, StrEq("------ 0.000s was the duration of '1' ------\n"));
+    EXPECT_THAT(getTempFileCounts(kTestDataPath), Eq(0));
 }