Add optional logging for timing of VFS operations.

test/src/unit-capi-config.cc

@@ -316,6 +316,7 @@ void check_save_to_file() {
   ss << "vfs.gcs.multi_part_size 5242880\n";
   ss << "vfs.gcs.request_timeout_ms 3000\n";
   ss << "vfs.gcs.use_multi_part_upload true\n";
+  ss << "vfs.log_operations false\n";
   ss << "vfs.max_batch_size 104857600\n";
   ss << "vfs.min_batch_gap 512000\n";
   ss << "vfs.min_batch_size 20971520\n";
@@ -695,6 +696,7 @@ TEST_CASE("C API: Test config iter", "[capi][config]") {
   all_param_values["vfs.min_parallel_size"] = "10485760";
   all_param_values["vfs.read_ahead_size"] = "102400";
   all_param_values["vfs.read_ahead_cache_size"] = "10485760";
+  all_param_values["vfs.log_operations"] = "false";
   all_param_values["vfs.read_logging_mode"] = "";
   all_param_values["vfs.gcs.endpoint"] = "";
   all_param_values["vfs.gcs.project_id"] = "";
@@ -769,6 +771,7 @@ TEST_CASE("C API: Test config iter", "[capi][config]") {
   vfs_param_values["min_parallel_size"] = "10485760";
   vfs_param_values["read_ahead_size"] = "102400";
   vfs_param_values["read_ahead_cache_size"] = "10485760";
+  vfs_param_values["log_operations"] = "false";
   vfs_param_values["read_logging_mode"] = "";
   vfs_param_values["gcs.endpoint"] = "";
   vfs_param_values["gcs.project_id"] = "";

test/src/unit-cppapi-config.cc

@@ -75,7 +75,7 @@ TEST_CASE("C++ API: Config iterator", "[cppapi][config]") {
     names.push_back(it->first);
   }
   // Check number of VFS params in default config object.
-  CHECK(names.size() == 69);
+  CHECK(names.size() == 70);
 }
 
 TEST_CASE("C++ API: Config Environment Variables", "[cppapi][config]") {

test/src/unit-vfs.cc

@@ -138,7 +138,8 @@ std::string local_path() {
 TEST_CASE("VFS: Test long local paths", "[vfs]") {
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
-  VFS vfs{&g_helper_stats, &compute_tp, &io_tp, Config{}};
+  VFS vfs{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, Config{}};
 
   SECTION("- Deep hierarchy") {
     // Create a nested path with a long total length
@@ -209,7 +210,8 @@ TEMPLATE_LIST_TEST_CASE(
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
   Config config = set_config_params();
-  VFS vfs{&g_helper_stats, &compute_tp, &io_tp, config};
+  VFS vfs{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, config};
 
   URI path = fs.temp_dir_.add_trailing_slash();
 
@@ -443,7 +445,8 @@ TEMPLATE_LIST_TEST_CASE("VFS: File I/O", "[vfs][uri][file_io]", AllBackends) {
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
   Config config = set_config_params(disable_multipart, max_parallel_ops);
-  VFS vfs{&g_helper_stats, &compute_tp, &io_tp, config};
+  VFS vfs{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, config};
 
   // Getting file_size on a nonexistent blob shouldn't crash on Azure
   uint64_t nbytes = 0;
@@ -562,7 +565,8 @@ TEST_CASE("VFS: Test end-to-end", "[.vfs-e2e]") {
   // Will be configured from environment variables.
   Config config;
 
-  VFS vfs{&g_helper_stats, &compute_tp, &io_tp, config};
+  VFS vfs{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, config};
   REQUIRE(vfs.supports_uri_scheme(test_file));
 
   uint64_t nbytes = 0;
@@ -573,7 +577,8 @@ TEST_CASE("VFS: Test end-to-end", "[.vfs-e2e]") {
 TEST_CASE("VFS: test ls_with_sizes", "[vfs][ls-with-sizes]") {
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
-  VFS vfs_ls{&g_helper_stats, &compute_tp, &io_tp, Config{}};
+  VFS vfs_ls{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, Config{}};
 
   std::string path = local_path();
   std::string dir = path + "ls_dir";
@@ -709,7 +714,7 @@ TEST_CASE(
 
 TEST_CASE("VFS: Test remove_dir_if_empty", "[vfs][remove-dir-if-empty]") {
   ThreadPool tp(1);
-  VFS vfs{&g_helper_stats, &tp, &tp, Config{}};
+  VFS vfs{&g_helper_stats, g_helper_logger().get(), &tp, &tp, Config{}};
 
   std::string path = local_path();
   std::string dir = path + "remove_dir_if_empty/";

test/support/src/vfs_helpers.cc

@@ -443,7 +443,12 @@ VFSTestBase::VFSTestBase(
     : test_tree_(test_tree)
     , compute_(4)
     , io_(4)
-    , vfs_(&tiledb::test::g_helper_stats, &io_, &compute_, create_test_config())
+    , vfs_(
+          &tiledb::test::g_helper_stats,
+          tiledb::test::g_helper_logger().get(),
+          &io_,
+          &compute_,
+          create_test_config())
     , prefix_(prefix)
     , temp_dir_(tiledb::test::test_dir(prefix_))
     , is_supported_(vfs_.supports_uri_scheme(temp_dir_)) {

tiledb/api/c_api/config/config_api_external.h

@@ -372,6 +372,10 @@ TILEDB_EXPORT void tiledb_config_free(tiledb_config_t** config) TILEDB_NOEXCEPT;
  * - `vfs.read_ahead_cache_size` <br>
  *    The the total maximum size of the read-ahead cache, which is an LRU. <br>
  *    **Default**: 10485760
+ * -  `vfs.log_operations` <br>
+ *    Enables logging all VFS operations in trace mode.
+ *    <br>
+ *    **Default**: false
  * - `vfs.min_parallel_size` <br>
  *    The minimum number of bytes in a parallel VFS operation
  *    (except parallel S3 writes, which are controlled by

tiledb/api/c_api/vfs/vfs_api.cc

@@ -58,14 +58,16 @@ capi_return_t tiledb_vfs_alloc(
 
   // Create VFS object
   auto& resources{ctx->resources()};
+  auto logger{resources.logger().get()};
   auto& stats{resources.stats()};
   auto& compute_tp{resources.compute_tp()};
   auto& io_tp{resources.io_tp()};
   auto& ctx_config{resources.config()};
   if (config) {
     ctx_config.inherit((config->config()));
   }
-  *vfs = tiledb_vfs_t::make_handle(&stats, &compute_tp, &io_tp, ctx_config);
+  *vfs = tiledb_vfs_t::make_handle(
+      &stats, logger, &compute_tp, &io_tp, ctx_config);
 
   return TILEDB_OK;
 }

tiledb/api/c_api/vfs/vfs_api_internal.h

@@ -56,10 +56,11 @@ struct tiledb_vfs_handle_t
  public:
   explicit tiledb_vfs_handle_t(
       tiledb::sm::stats::Stats* parent_stats,
+      Logger* logger,
       ThreadPool* compute_tp,
       ThreadPool* io_tp,
       const tiledb::sm::Config& config)
-      : vfs_{parent_stats, compute_tp, io_tp, config} {
+      : vfs_{parent_stats, logger, compute_tp, io_tp, config} {
   }
 
   vfs_type* vfs() {

tiledb/common/log_duration_instrument.h

@@ -0,0 +1,126 @@
+/**
+ * @file   log_duration_instrument.h
+ *
+ * @section LICENSE
+ *
+ * The MIT License
+ *
+ * @copyright Copyright (c) 2024 TileDB, Inc.
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in
+ * all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+ * THE SOFTWARE.
+ *
+ * @section DESCRIPTION
+ *
+ * This file defines class `LogDurationInstrument`.
+ */
+
+#ifndef TILEDB_LOG_DURATION_INSTRUMENT_H
+#define TILEDB_LOG_DURATION_INSTRUMENT_H
+
+#include <spdlog/fmt/fmt.h>
+
+#include <spdlog/fmt/chrono.h>
+
+#include "tiledb/common/logger.h"
+
+namespace tiledb::common {
+
+/**
+ * Emits log messages on the start and end of a scope, noting the scope's
+ * duration.
+ */
+class LogDurationInstrument {
+ public:
+  LogDurationInstrument() = delete;
+
+  DISABLE_COPY_AND_COPY_ASSIGN(LogDurationInstrument);
+  DISABLE_MOVE_AND_MOVE_ASSIGN(LogDurationInstrument);
+
+  /**
+   * Constructor.
+   *
+   * @param logger The logger to use.
+   * @param fmt The format string to describe the operation.
+   * @param args Arguments for the format string.
+   */
+  template <typename... Args>
+  LogDurationInstrument(
+      Logger* logger,
+      // Ideally this would be a fmt::format_string<Args...> but it fails with
+      // weird constexpr-related compile errors.
+      const std::string& fmt,
+      Args&&... args) {
+    assert(logger);
+
+    if (logger->should_log(DefaultLevel)) {
+      logger_ = logger;
+      // Forwarding args in make_format_args causes an error.
+      event_name_ = fmt::vformat(fmt, fmt::make_format_args(args...));
+      start_ = std::chrono::high_resolution_clock::now();
+      system_time_start_ = std::chrono::system_clock::now();
+    }
+  }
+
+  ~LogDurationInstrument() {
+    try {
+      if (logger_) {
+        auto end = std::chrono::high_resolution_clock::now();
+        std::chrono::duration<float, std::chrono::milliseconds::period>
+            duration = end - start_;
+        logger_->log(
+            DefaultLevel,
+            "{} started at {:%Y-%m-%d %X} and lasted {}",
+            event_name_,
+            system_time_start_,
+            duration);
+      }
+    } catch (...) {
+      // Ignore exceptions inside destructor.
+    }
+  }
+
+ private:
+  /** Level used for logging. */
+  static constexpr Logger::Level DefaultLevel = Logger::Level::TRACE;
+
+  /**
+   * A pointer to the logger to use for logging.
+   *
+   * A null pointer indicates that the logger is not enabled for the given
+   * level and no event should be emitted.
+   */
+  Logger* logger_;
+
+  /** High-resolution time point of the operation's start. */
+  std::chrono::time_point<std::chrono::high_resolution_clock> start_;
+
+  /**
+   * System time point of the operation's start.
+   *
+   * We use it to format the operation's start time.
+   */
+  std::chrono::time_point<std::chrono::system_clock> system_time_start_;
+
+  /** Name of the event that will be logged. */
+  std::string event_name_;
+};
+
+}  // namespace tiledb::common
+
+#endif  // TILEDB_LOG_DURATION_INSTRUMENT_H

tiledb/common/logger.cc

@@ -142,6 +142,10 @@ void Logger::fatal(const char* msg) {
   exit(1);
 }
 
+void Logger::log(Logger::Level level, const char* msg) {
+  logger_->log(to_spdlog_level(level), msg);
+}
+
 Status Logger::status(const Status& st) {
   logger_->error(st.message());
   return st;
@@ -176,6 +180,10 @@ void Logger::fatal(const std::string& msg) {
   exit(1);
 }
 
+void Logger::log(Logger::Level level, const std::string& msg) {
+  logger_->log(to_spdlog_level(level), msg);
+}
+
 void Logger::trace(const std::stringstream& msg) {
   logger_->trace(msg.str());
 }
@@ -205,6 +213,10 @@ void Logger::fatal(const std::stringstream& msg) {
   exit(1);
 }
 
+void Logger::log(Logger::Level level, const std::stringstream& msg) {
+  logger_->log(to_spdlog_level(level), msg.str());
+}
+
 bool Logger::should_log(Logger::Level lvl) {
   return logger_->should_log(to_spdlog_level(lvl));
 }

tiledb/common/logger.h

@@ -335,6 +335,46 @@ class Logger {
    */
   void fatal(const std::stringstream& msg);
 
+  /**
+   * Logs a message at the given level with no formatting.
+   *
+   * @param lvl The level of the log message.
+   * @param msg The message to log.
+   */
+  void log(const Level lvl, const char* msg);
+
+  /**
+   * Logs a message at the given level with no formatting.
+   *
+   * @param lvl The level of the log message.
+   * @param msg The message to log.
+   */
+  void log(const Level lvl, const std::string& msg);
+
+  /**
+   * Logs a message at the given level with no formatting.
+   *
+   * @param lvl The level of the log message.
+   * @param msg The message to log.
+   */
+  void log(const Level lvl, const std::stringstream& msg);
+
+  /**
+   * Logs a formatted message at the given level.
+   *
+   * @param lvl The level of the log message.
+   * @param msg The message to log.
+   */
+  template <typename... Args>
+  void log(const Level lvl, fmt::format_string<Args...> fmt, Args&&... args) {
+    // Check that this level is enabled to avoid needlessly formatting the
+    // string.
+    if (!should_log(lvl)) {
+      return;
+    }
+    log(lvl, fmt::format(fmt, std::forward<Args>(args)...));
+  }
+
   /**
    * Check whether events of a given level are logged.
    *

tiledb/sm/config/config.cc

@@ -175,6 +175,7 @@ const std::string Config::VFS_FILE_POSIX_FILE_PERMISSIONS = "644";
 const std::string Config::VFS_FILE_POSIX_DIRECTORY_PERMISSIONS = "755";
 const std::string Config::VFS_READ_AHEAD_SIZE = "102400";          // 100KiB
 const std::string Config::VFS_READ_AHEAD_CACHE_SIZE = "10485760";  // 10MiB;
+const std::string VFS_LOG_OPERATIONS = "false";
 const std::string Config::VFS_READ_LOGGING_MODE = "";
 const std::string Config::VFS_AZURE_STORAGE_ACCOUNT_NAME = "";
 const std::string Config::VFS_AZURE_STORAGE_ACCOUNT_KEY = "";
@@ -404,6 +405,7 @@ const std::map<std::string, std::string> default_config_values = {
     std::make_pair("vfs.min_batch_gap", Config::VFS_MIN_BATCH_GAP),
     std::make_pair("vfs.min_batch_size", Config::VFS_MIN_BATCH_SIZE),
     std::make_pair("vfs.read_ahead_size", Config::VFS_READ_AHEAD_SIZE),
+    std::make_pair("vfs.log_operations", VFS_LOG_OPERATIONS),
     std::make_pair(
         "vfs.read_ahead_cache_size", Config::VFS_READ_AHEAD_CACHE_SIZE),
     std::make_pair(

tiledb/sm/cpp_api/config.h

@@ -545,6 +545,9 @@ class Config {
    *    The the total maximum size of the read-ahead cache, which is an LRU.
    *    <br>
    *    **Default**: 10485760
+   * -  `vfs.log_operations` <br>
+   *    Enables logging all VFS operations in trace mode. <br>
+   *    **Default**: false
    * - `vfs.min_parallel_size` <br>
    *    The minimum number of bytes in a parallel VFS operation
    *    (except parallel S3 writes, which are controlled by

tiledb/sm/filesystem/test/compile_vfs_main.cc

@@ -27,11 +27,13 @@
  */
 
 #include "../vfs.h"
+#include "tiledb/common/logger.h"
 
 int main() {
   static tiledb::sm::stats::Stats stats("test");
+  static tiledb::common::Logger logger("test");
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
-  tiledb::sm::VFS x{&stats, &compute_tp, &io_tp, tiledb::sm::Config{}};
+  tiledb::sm::VFS x{&stats, &logger, &compute_tp, &io_tp, tiledb::sm::Config{}};
   return 0;
 }