[ui] add cpu/mem consumed for indexing a file

Related to #1689

Author: tstack

NEWS.md

@@ -43,7 +43,12 @@ Features:
   separator will be automatically detected and the header
   compared against the columns defined in the tabular
   formats.  If a good match is found, it will be used as
-  the format for the file.
+  the format for the file.  Quoted cells that span
+  multiple physical lines (an embedded LF inside `"..."`)
+  are stitched back into a single log message, so an
+  Excel-exported CSV with a multi-line free-text column
+  shows one logline per row and SQL/search operates on
+  the merged cell value.
 * Added a log format for the `fsck_apfs` and `fsck_hfs` tools on
   macOS, covering both the `started`/`completed` lifecycle lines
   and legacy `run` entries.  This replaces the previous
@@ -67,6 +72,19 @@ Features:
   from a HyperLogLog sketch (~4 KB per text column,
   ~1.6% standard error).  Stats render in the column's
   declared unit when one is set.
+* The FILES panel now reports per-file indexing cost: an
+  `Index Time` row shows cumulative wall-clock vs.
+  thread-CPU spent indexing the file.  In addition,
+  `Index Memory` and `Line Buffer` rows show allocations
+  for indexing and I/O-cache.  The same data is queryable
+  as a JSON object through the new `stats` column on the
+  `lnav_file` SQL vtab, with keys `polls`, `reads`,
+  `index/wall-us`, `index/cpu-us`, `index/memory-bytes`,
+  and `line-buffer-memory-bytes`.
+* The `humanize_duration()` SQL function now preserves
+  nanosecond inputs: a value like `0.0000001` (100 ns)
+  renders as `"100ns"` instead of being floored to
+  `"0s"`.
 
 Interface Changes:
 * Moving horizontally now defaults to moving to the

src/CMakeLists.txt

@@ -730,7 +730,6 @@ add_library(
         logfile_sub_source.cfg.hh
         logfile.hh
         logfile_fwd.hh
-        logfile_stats.hh
         logline_window.hh
         md2attr_line.hh
         md4cpp.hh

src/base/humanize.cc

@@ -500,11 +500,9 @@ format(double value, string_fragment suffix, alignment align)
             const auto sr = si_scale(value, -4);
             return fmt::format(FMT_STRING("{:.3g}{}s"), sr.value, sr.prefix);
         }
-        timeval tv;
-        const auto secs = std::trunc(value);
-        tv.tv_sec = static_cast<time_t>(secs);
-        tv.tv_usec = static_cast<suseconds_t>((value - secs) * 1e6);
-        return humanize::time::duration::from_tv(tv).to_string();
+        return humanize::time::duration::from(
+                   std::chrono::duration<double>{value})
+            .to_string();
     }
     // Any other suffix gets up-only SI scaling so large counts /
     // rates / frequencies render compactly (e.g. `1.2kHz`,

src/base/humanize.time.cc

@@ -139,12 +139,6 @@ point::as_precise_time_ago() const
     return this->as_time_ago();
 }
 
-duration
-duration::from_tv(const timeval& tv)
-{
-    return duration{tv};
-}
-
 std::string
 duration::to_string() const
 {
@@ -163,33 +157,66 @@ duration::to_string() const
     };
 
     const auto* curr_interval = intervals;
-    auto usecs = to_us(this->d_timeval);
+    auto nsecs = this->d_nsecs;
     std::string retval;
     bool neg = false;
 
-    if (usecs == 0us) {
+    if (nsecs == 0ns) {
         if (!this->d_compact) {
             retval = "0s";
         }
         return retval;
     }
 
-    if (usecs < 0s) {
+    if (nsecs < 0ns) {
         neg = true;
-        usecs = -usecs;
+        nsecs = -nsecs;
     }
 
-    if (usecs < 1ms) {
-        return fmt::format(FMT_STRING("{}us"), usecs.count());
+    // Sub-microsecond: render as `Nns`.  Always emitted at full
+    // precision — there's no segmented form below `us`, and rounding
+    // the only value we have produces zeros.
+    if (nsecs < 1us) {
+        auto out = fmt::format(FMT_STRING("{}ns"), nsecs.count());
+        if (neg) {
+            out.insert(0, "-");
+        }
+        return out;
     }
 
-    uint64_t remaining = usecs.count() / 1000;
-    uint64_t scale = 1;
-    if (this->d_msecs_resolution > 0) {
-        remaining = roundup(remaining, this->d_msecs_resolution);
+    // `[1us, 1ms)`: render as `Nus`, truncating any sub-microsecond
+    // remainder.  Matches the pre-nanosecond behavior of the old
+    // timeval-based path which couldn't represent sub-us anyway.
+    if (nsecs < 1ms) {
+        auto usecs
+            = std::chrono::duration_cast<std::chrono::microseconds>(nsecs);
+        auto out = fmt::format(FMT_STRING("{}us"), usecs.count());
+        if (neg) {
+            out.insert(0, "-");
+        }
+        return out;
+    }
+
+    // `>= 1ms`: fall into the segmented hh/mm/ss/ms peeling loop.
+    // Resolution is interpreted in milliseconds here; anything finer
+    // (e.g. `with_resolution(1ns)`) collapses to a 1ms floor — full
+    // sub-ms precision in the segmented form would require extending
+    // the intervals table below the ms tier.
+    auto resolution_ms
+        = std::chrono::duration_cast<std::chrono::milliseconds>(
+              this->d_resolution)
+              .count();
+    if (resolution_ms < 1) {
+        resolution_ms = 1;
     }
+
+    uint64_t remaining
+        = std::chrono::duration_cast<std::chrono::milliseconds>(nsecs)
+              .count();
+    uint64_t scale = 1;
+    remaining = roundup(remaining, static_cast<uint64_t>(resolution_ms));
     auto skipped = 0;
-    if (usecs >= 10min) {
+    if (nsecs >= 10min) {
         remaining /= curr_interval->length;
         scale *= curr_interval->length;
         ++curr_interval;
@@ -199,7 +226,7 @@ duration::to_string() const
     for (; curr_interval != std::end(intervals); curr_interval++) {
         uint64_t amount;
         char segment[32];
-        auto skip = scale < this->d_msecs_resolution;
+        auto skip = scale < static_cast<uint64_t>(resolution_ms);
 
         if (curr_interval->length) {
             amount = remaining % curr_interval->length;

src/base/humanize.time.hh

@@ -77,30 +77,42 @@ private:
 
 class duration {
 public:
-    static duration from_tv(const timeval& tv);
+    // Accept any chrono::duration source and canonicalize to ns.
+    // Lets callers pass e.g. `std::chrono::nanoseconds`, `microseconds`,
+    // or a `steady_clock::duration` directly.
+    template<class Rep, class Period>
+    static duration from(const std::chrono::duration<Rep, Period>& d)
+    {
+        return duration{
+            std::chrono::duration_cast<std::chrono::nanoseconds>(d)};
+    }
 
     duration& with_compact(bool compact)
     {
         this->d_compact = compact;
         return *this;
     }
 
+    // The smallest unit `to_string()` will render.  Sub-microsecond
+    // values (below `1us`) always print as `Nns` regardless of this;
+    // values in `[1us, 1ms)` print as `Nus`; for `>= 1ms`, the
+    // resolution is interpreted in milliseconds (anything finer than
+    // 1ms collapses to 1ms in the segmented hh/mm/ss/ms output).
     template<class Rep, class Period>
     duration& with_resolution(const std::chrono::duration<Rep, Period>& res)
     {
-        this->d_msecs_resolution
-            = std::chrono::duration_cast<std::chrono::milliseconds>(res)
-                  .count();
+        this->d_resolution
+            = std::chrono::duration_cast<std::chrono::nanoseconds>(res);
         return *this;
     }
 
     [[nodiscard]] std::string to_string() const;
 
 private:
-    explicit duration(const timeval& tv) : d_timeval(tv) {}
+    explicit duration(std::chrono::nanoseconds d) : d_nsecs(d) {}
 
-    timeval d_timeval;
-    uint64_t d_msecs_resolution{1};
+    std::chrono::nanoseconds d_nsecs{0};
+    std::chrono::nanoseconds d_resolution{std::chrono::milliseconds{1}};
     bool d_compact{true};
 };
 

src/base/humanize.time.tests.cc

@@ -103,31 +103,74 @@ TEST_CASE("time ago")
 
 TEST_CASE("duration to_string")
 {
+    using namespace std::chrono_literals;
     std::string val;
 
-    val = humanize::time::duration::from_tv({15 * 60, 0})
+    val = humanize::time::duration::from(15min)
               .with_compact(false)
               .to_string();
     CHECK(val == "15m00s");
-    val = humanize::time::duration::from_tv({0, 100000})
-              .with_compact(false)
-              .to_string();
+    val = humanize::time::duration::from(100ms).with_compact(false).to_string();
     CHECK(val == "100ms");
-    val = humanize::time::duration::from_tv({25 * 60 * 60, 123000}).to_string();
+    val = humanize::time::duration::from(25h + 123ms).to_string();
     CHECK(val == "1d01h00m00s");
-    val = humanize::time::duration::from_tv({25 * 60 * 60 + 25 * 60, 123000})
-              .to_string();
+    val = humanize::time::duration::from(25h + 25min + 123ms).to_string();
     CHECK(val == "1d01h25m00s");
-    val = humanize::time::duration::from_tv({10, 123000}).to_string();
+    val = humanize::time::duration::from(10s + 123ms).to_string();
     CHECK(val == "10s123");
-    val = humanize::time::duration::from_tv({10, 0}).to_string();
+    val = humanize::time::duration::from(10s).to_string();
     CHECK(val == "10s");
-    val = humanize::time::duration::from_tv({0, 100000}).to_string();
+    val = humanize::time::duration::from(100ms).to_string();
     CHECK(val == "100");
-    val = humanize::time::duration::from_tv({0, 0}).to_string();
+    val = humanize::time::duration::from(0s).to_string();
     CHECK(val == "");
-    val = humanize::time::duration::from_tv({0, -10000}).to_string();
+    val = humanize::time::duration::from(-10ms).to_string();
     CHECK(val == "-010");
-    val = humanize::time::duration::from_tv({-10, 0}).to_string();
+    val = humanize::time::duration::from(-10s).to_string();
     CHECK(val == "-10s");
 }
+
+TEST_CASE("duration nanosecond input")
+{
+    using namespace std::chrono_literals;
+    std::string val;
+
+    // Sub-microsecond → `Nns`, full precision regardless of resolution.
+    val = humanize::time::duration::from(500ns).to_string();
+    CHECK(val == "500ns");
+
+    // Negative sub-microsecond carries the leading sign.
+    val = humanize::time::duration::from(-1ns).to_string();
+    CHECK(val == "-1ns");
+
+    // `[1us, 1ms)` → `Nus`, sub-microsecond remainder dropped (matches
+    // pre-nanosecond timeval truncation behavior).
+    val = humanize::time::duration::from(1234ns).to_string();
+    CHECK(val == "1us");
+
+    val = humanize::time::duration::from(999us + 999ns).to_string();
+    CHECK(val == "999us");
+
+    // `>= 1ms` falls into the segmented path; sub-millisecond
+    // precision collapses to 1ms (the existing format doesn't carry
+    // sub-ms segments).
+    val = humanize::time::duration::from(1ms + 500us).to_string();
+    CHECK(val == "001");
+
+    val = humanize::time::duration::from(10s + 123ms + 456us).to_string();
+    CHECK(val == "10s123");
+
+    // Zero stays empty in compact mode regardless of source duration.
+    val = humanize::time::duration::from(0ns).to_string();
+    CHECK(val == "");
+    val = humanize::time::duration::from(0ns).with_compact(false).to_string();
+    CHECK(val == "0s");
+
+    // with_resolution(ns) doesn't grant sub-ms precision in the
+    // segmented path — explicitly characterize the floor so a future
+    // extension shows up as a diff.
+    val = humanize::time::duration::from(10s + 123ms + 456us)
+              .with_resolution(1ns)
+              .to_string();
+    CHECK(val == "10s123");
+}

src/base/time_util.hh

@@ -52,6 +52,15 @@ to_us(const timeval& tv)
         + std::chrono::microseconds{tv.tv_usec};
 }
 
+inline std::chrono::microseconds
+to_us(const timespec& ts)
+{
+    return std::chrono::duration_cast<std::chrono::microseconds>(
+               std::chrono::seconds{ts.tv_sec})
+        + std::chrono::duration_cast<std::chrono::microseconds>(
+               std::chrono::nanoseconds{ts.tv_nsec});
+}
+
 namespace lnav {
 
 using time64_t = uint64_t;

src/command_executor.cc

@@ -272,8 +272,8 @@ bind_sql_parameters(exec_context& ec, sqlite3_stmt* stmt)
                 } else {
                     auto zoom_level
                         = ec.ec_label_source_stack.back()->get_zoom_level();
-                    auto zoom_level_str = humanize::time::duration::from_tv(
-                                              to_timeval(zoom_level))
+                    auto zoom_level_str = humanize::time::duration::from(
+                                              zoom_level)
                                               .with_compact(false)
                                               .to_string();
 

src/db_status_source.cc

@@ -89,7 +89,7 @@ db_status_source::update_from_db_source()
         if (dls.dls_query_end.has_value()) {
             auto dur_us = std::chrono::duration_cast<std::chrono::microseconds>(
                 dls.dls_query_end.value() - dls.dls_query_start.value());
-            auto dur = humanize::time::duration::from_tv(to_timeval(dur_us))
+            auto dur = humanize::time::duration::from(dur_us)
                            .with_compact(false)
                            .to_string();
             timing_al.append("ran ").append(lnav::roles::time_ago(ago));

src/field_overlay_source.cc

@@ -152,7 +152,8 @@ field_overlay_source::build_field_lines(const listview_curses& lv,
     }
 
     char old_timestamp[64], curr_timestamp[64], orig_timestamp[64];
-    timeval curr_tv, offset_tv, orig_tv, diff_tv = {0, 0};
+    timeval curr_tv, offset_tv, orig_tv;
+    std::chrono::microseconds diff{0};
     attr_line_t time_line;
     auto& time_str = time_line.get_string();
     line_range time_lr;
@@ -256,11 +257,11 @@ field_overlay_source::build_field_lines(const listview_curses& lv,
             time_line.with_attr(
                 string_attr(time_lr, VC_ROLE.value(role_t::VCR_SKEWED_TIME)));
 
-            timersub(&curr_tv, &actual_tv, &diff_tv);
+            diff = to_us(curr_tv) - to_us(actual_tv);
             time_str.append(";  Diff: ");
             time_lr.lr_start = time_str.length();
             time_str.append(
-                humanize::time::duration::from_tv(diff_tv).to_string());
+                humanize::time::duration::from(diff).to_string());
             time_lr.lr_end = time_str.length();
             time_line.with_attr(
                 string_attr(time_lr, VC_STYLE.value(text_attrs::with_bold())));
@@ -305,7 +306,7 @@ field_overlay_source::build_field_lines(const listview_curses& lv,
     }
 
     if ((!this->fos_contexts.empty() && this->fos_contexts.top().c_show)
-        || diff_tv.tv_sec > 0 || ll->is_time_skewed())
+        || diff >= std::chrono::seconds{1} || ll->is_time_skewed())
     {
         this->fos_lines.emplace_back(time_line);
     }