[MISC] Add complete search and cpu timer

include/raptor/argument_parsing/cpu_time.hpp

@@ -0,0 +1,75 @@
+// --------------------------------------------------------------------------------------------------
+// Copyright (c) 2006-2023, Knut Reinert & Freie Universität Berlin
+// Copyright (c) 2016-2023, Knut Reinert & MPI für molekulare Genetik
+// This file may be used, modified and/or redistributed under the terms of the 3-clause BSD-License
+// shipped with this file and also available at: https://github.com/seqan/raptor/blob/main/LICENSE.md
+// --------------------------------------------------------------------------------------------------
+
+/*!\file
+ * \brief Provides raptor::get_cpu_time.
+ * \author Enrico Seiler <enrico.seiler AT fu-berlin.de>
+ */
+
+#pragma once
+
+#include <algorithm>
+#include <cassert>
+#include <chrono>
+
+#if __has_include(<sys/resource.h>)
+#    include <sys/resource.h>
+#endif
+
+namespace raptor
+{
+
+struct cpu_time_t
+{
+    double user_time_in_seconds{};
+    double system_time_in_seconds{};
+
+    void operator-=(double const diff) noexcept
+    {
+        user_time_in_seconds -= diff;
+    }
+
+    [[nodiscard]] double cpu_usage_in_percent(double const elapsed_time_in_seconds,
+                                              uint8_t const threads) const noexcept
+    {
+        assert(is_valid());
+        assert(elapsed_time_in_seconds > 0.0);
+        return std::min<double>(100.0 * threads,
+                                100.0 * (user_time_in_seconds + system_time_in_seconds) / elapsed_time_in_seconds);
+    }
+
+    [[nodiscard]] bool is_valid() const noexcept
+    {
+        return (user_time_in_seconds + system_time_in_seconds) >= 0.0;
+    }
+};
+
+#if __has_include(<sys/resource.h>)
+// Returns cpu_time_t{-1.0, -1.0} if not available.
+[[nodiscard]] inline cpu_time_t get_cpu_time()
+{
+    rusage usage;
+
+    if (getrusage(RUSAGE_SELF, &usage) != 0)
+        return cpu_time_t{-1.0, -1.0}; // GCOVR_EXCL_LINE
+
+    std::chrono::duration user_time =
+        std::chrono::seconds{usage.ru_utime.tv_sec} + std::chrono::microseconds{usage.ru_utime.tv_usec};
+    std::chrono::duration system_time =
+        std::chrono::seconds{usage.ru_stime.tv_sec} + std::chrono::microseconds{usage.ru_stime.tv_usec};
+
+    return cpu_time_t{.user_time_in_seconds = std::chrono::duration<double>(user_time).count(),
+                      .system_time_in_seconds = std::chrono::duration<double>(system_time).count()};
+}
+#else
+[[nodiscard]] inline cpu_time_t get_cpu_time()
+{
+    return cpu_time_t{-1.0, -1.0};
+}
+#endif
+
+} // namespace raptor

include/raptor/argument_parsing/search_arguments.hpp

@@ -65,6 +65,8 @@ struct search_arguments
     mutable seqan::hibf::concurrent_timer compute_minimiser_timer{};
     mutable seqan::hibf::concurrent_timer query_ibf_timer{};
     mutable seqan::hibf::concurrent_timer generate_results_timer{};
+    mutable seqan::hibf::concurrent_timer complete_search_timer{};
+    mutable seqan::hibf::concurrent_timer parallel_search_timer{};
 
     void print_timings() const;
     void write_timings_to_file() const;

include/raptor/search/search_singular_ibf.hpp

@@ -149,7 +149,9 @@ void search_singular_ibf(search_arguments const & arguments, index_t && index)
         cereal_future.get();
         [[maybe_unused]] static bool header_written = write_header(); // called exactly once
 
+        arguments.parallel_search_timer.start();
         do_parallel(worker, records.size(), arguments.threads);
+        arguments.parallel_search_timer.stop();
     }
 }
 

src/argument_parsing/build_arguments.cpp

@@ -13,6 +13,7 @@
 #include <fstream>
 
 #include <raptor/argument_parsing/build_arguments.hpp>
+#include <raptor/argument_parsing/cpu_time.hpp>
 #include <raptor/argument_parsing/formatted_index_size.hpp>
 #include <raptor/argument_parsing/memory_usage.hpp>
 
@@ -22,83 +23,118 @@ namespace raptor
 void build_arguments::print_timings() const
 {
     std::cerr << std::fixed << std::setprecision(2) << "============= Timings =============\n";
-    std::cerr << "Wall clock time [s]: " << wall_clock_timer.in_seconds() << '\n';
     std::cerr << "Peak memory usage " << formatted_peak_ram() << '\n';
     std::cerr << "Index size " << formatted_index_size(out_path, parts) << '\n';
+    std::cerr << "Configured threads: " << static_cast<size_t>(threads) << '\n';
+    std::cerr << "Wall clock time [s]: " << wall_clock_timer.in_seconds() << '\n';
+
+    if (cpu_time_t cpu_time = get_cpu_time(); cpu_time.is_valid())
+    {
+        std::cerr << "├── User time [s]: " << cpu_time.user_time_in_seconds << '\n';
+        std::cerr << "├── System time [s]: " << cpu_time.system_time_in_seconds << '\n';
+        std::cerr << "├── CPU usage [%]: " << cpu_time.cpu_usage_in_percent(wall_clock_timer.in_seconds(), threads)
+                  << '\n';
+    }
+    else
+    {
+        std::cerr << "├── User time [s]: Not available\n";   // GCOVR_EXCL_LINE
+        std::cerr << "├── System time [s]: Not available\n"; // GCOVR_EXCL_LINE
+        std::cerr << "├── CPU usage [%]: Not available\n";   // GCOVR_EXCL_LINE
+    }
 
     if (is_hibf)
-        std::cerr << "Determine IBF size [s]: NA\n";
+        std::cerr << "├── Determine IBF size [s]: NA\n";
     else
-        std::cerr << "Determine IBF size [s]: " << bin_size_timer.in_seconds() << '\n';
+        std::cerr << "├── Determine IBF size [s]: " << bin_size_timer.in_seconds() << '\n';
 
-    std::cerr << "Index allocation [s]: " << index_allocation_timer.in_seconds() << '\n';
-    std::cerr << "User bin I/O avg per thread [s]: " << user_bin_io_timer.in_seconds() / threads << '\n';
-    std::cerr << "User bin I/O sum [s]: " << user_bin_io_timer.in_seconds() << '\n';
+    std::cerr << "├── Index allocation [s]: " << index_allocation_timer.in_seconds() << '\n';
+    std::cerr << "├── User bin I/O\n";
+    std::cerr << "│   ├── Max [s]: " << user_bin_io_timer.max_in_seconds() << '\n';
+    std::cerr << "│   └── Avg [s]: " << user_bin_io_timer.avg_in_seconds() << '\n';
+    std::cerr << "├── Merge kmer sets I/O\n";
 
     if (is_hibf)
     {
-        std::cerr << "Merge kmer sets avg per thread [s]: " << merge_kmers_timer.in_seconds() / threads << '\n';
-        std::cerr << "Merge kmer sets sum [s]: " << merge_kmers_timer.in_seconds() << '\n';
+        std::cerr << "│   ├── Max [s]: " << merge_kmers_timer.max_in_seconds() << '\n';
+        std::cerr << "│   └── Avg [s]: " << merge_kmers_timer.avg_in_seconds() << '\n';
     }
     else
     {
-        std::cerr << "Merge kmer sets avg per thread [s]: NA\n";
-        std::cerr << "Merge kmer sets sum [s]: NA\n";
+        std::cerr << "│   ├── Max [s]: NA\n";
+        std::cerr << "│   └── Avg [s]: NA\n";
     }
 
-    std::cerr << "Fill IBF avg per thread [s]: " << fill_ibf_timer.in_seconds() / threads << '\n';
-    std::cerr << "Fill IBF sum [s]: " << fill_ibf_timer.in_seconds() << '\n';
-    std::cerr << "Store index [s]: " << store_index_timer.in_seconds() << '\n';
+    std::cerr << "├── Fill IBF\n";
+    std::cerr << "│   ├── Max [s]: " << fill_ibf_timer.max_in_seconds() << '\n';
+    std::cerr << "│   └── Avg [s]: " << fill_ibf_timer.avg_in_seconds() << '\n';
+    std::cerr << "└── Store index [s]: " << store_index_timer.in_seconds() << '\n';
 }
 
 void build_arguments::write_timings_to_file() const
 {
     std::ofstream output_stream{timing_out};
     output_stream << std::fixed << std::setprecision(2);
-    output_stream << "wall_clock_time_in_seconds\t"
-                  << "peak_memory_usage_in_kibibytes\t"
+    output_stream << "peak_memory_usage_in_kibibytes\t"
                   << "index_size_in_kibibytes\t"
+                  << "configured_threads\t"
+                  << "wall_clock_time_in_seconds\t"
+                  << "user_time_in_seconds\t"
+                  << "system_time_in_seconds\t"
+                  << "cpu_usage_in_percent\t"
                   << "determine_ibf_size_in_seconds\t"
                   << "index_allocation_in_seconds\t"
-                  << "user_bin_io_avg_per_thread_in_seconds\t"
-                  << "user_bin_io_sum_in_seconds\t"
-                  << "merge_kmer_sets_avg_per_thread_in_seconds\t"
-                  << "merge_kmer_sets_sum_in_seconds\t"
-                  << "fill_ibf_avg_per_thread_in_seconds\t"
-                  << "fill_ibf_sum_in_seconds\t"
+                  << "user_bin_io_max_in_seconds\t"
+                  << "user_bin_io_avg_in_seconds\t"
+                  << "merge_kmer_sets_max_in_seconds\t"
+                  << "merge_kmer_sets_avg_in_seconds\t"
+                  << "fill_ibf_max_in_seconds\t"
+                  << "fill_ibf_avg_in_seconds\t"
                   << "store_index_in_seconds\n";
 
-    output_stream << wall_clock_timer.in_seconds() << '\t';
-
     if (long const peak_ram_KiB = peak_ram_in_KiB(); peak_ram_KiB != -1L)
         output_stream << peak_ram_KiB << '\t';
     else
         output_stream << "NA\t"; // GCOVR_EXCL_LINE
 
     output_stream << index_size_in_KiB(out_path, parts) << '\t';
+    output_stream << static_cast<size_t>(threads) << '\t';
+    output_stream << wall_clock_timer.in_seconds() << '\t';
+
+    if (cpu_time_t cpu_time = get_cpu_time(); cpu_time.is_valid())
+    {
+        output_stream << cpu_time.user_time_in_seconds << '\t';
+        output_stream << cpu_time.system_time_in_seconds << '\t';
+        output_stream << cpu_time.cpu_usage_in_percent(wall_clock_timer.in_seconds(), threads) << '\t';
+    }
+    else
+    {
+        output_stream << "NA\t"; // GCOVR_EXCL_LINE
+        output_stream << "NA\t"; // GCOVR_EXCL_LINE
+        output_stream << "NA\t"; // GCOVR_EXCL_LINE
+    }
 
     if (is_hibf)
         output_stream << "NA\t";
     else
         output_stream << bin_size_timer.in_seconds() << '\t';
 
     output_stream << index_allocation_timer.in_seconds() << '\t';
-    output_stream << user_bin_io_timer.in_seconds() / threads << '\t';
-    output_stream << user_bin_io_timer.in_seconds() << '\t';
+    output_stream << user_bin_io_timer.max_in_seconds() << '\t';
+    output_stream << user_bin_io_timer.avg_in_seconds() << '\t';
 
     if (is_hibf)
     {
-        output_stream << merge_kmers_timer.in_seconds() / threads << '\t';
-        output_stream << merge_kmers_timer.in_seconds() << '\t';
+        output_stream << merge_kmers_timer.max_in_seconds() << '\t';
+        output_stream << merge_kmers_timer.avg_in_seconds() << '\t';
     }
     else
     {
         output_stream << "NA\t";
         output_stream << "NA\t";
     }
 
-    output_stream << fill_ibf_timer.in_seconds() / threads << '\t';
-    output_stream << fill_ibf_timer.in_seconds() << '\t';
+    output_stream << fill_ibf_timer.max_in_seconds() << '\t';
+    output_stream << fill_ibf_timer.avg_in_seconds() << '\t';
     output_stream << store_index_timer.in_seconds() << '\n';
 }