Add optional logging for timing of VFS operations.

test/src/unit-capi-config.cc

@@ -319,6 +319,7 @@ void check_save_to_file() {
   ss << "vfs.min_batch_gap 512000\n";
   ss << "vfs.min_batch_size 20971520\n";
   ss << "vfs.min_parallel_size 10485760\n";
+  ss << "vfs.log_operations true\n";
   ss << "vfs.read_ahead_cache_size 10485760\n";
   ss << "vfs.read_ahead_size 102400\n";
   ss << "vfs.s3.bucket_canned_acl NOT_SET\n";
@@ -693,6 +694,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"] = "";
@@ -767,6 +769,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";

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 of the start and end of 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.h

@@ -0,0 +1,127 @@
+/**
+ * @file   log_duration.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 `LogDuration`.
+ */
+
+#ifndef TILEDB_LOG_DURATION_H
+#define TILEDB_LOG_DURATION_H
+
+#include <spdlog/fmt/fmt.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 LogDuration {
+ public:
+  LogDuration() = delete;
+
+  DISABLE_COPY_AND_COPY_ASSIGN(LogDuration);
+  DISABLE_MOVE_AND_MOVE_ASSIGN(LogDuration);
+
+  /**
+   * Constructor.
+   *
+   * The log level is set to TRACE.
+   *
+   * @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>
+  constexpr LogDuration(
+      Logger* logger,
+      // fmt::format_string<Args...> fmt,
+      const std::string& fmt,
+      Args&&... args)
+      : LogDuration(
+            logger,
+            Logger::Level::TRACE,
+            std::move(fmt),
+            std::forward<Args>(args)...) {
+  }
+
+  /**
+   * Constructor.
+   *
+   * @param logger The logger to use.
+   * @param level The level to log the event.
+   * @param fmt The format string to describe the operation.
+   * @param args Arguments for the format string.
+   */
+  template <typename... Args>
+  constexpr LogDuration(
+      Logger* logger,
+      Logger::Level level,
+      // fmt::format_string<Args...> fmt,
+      const std::string& fmt,
+      Args&&... args)
+      : level_(level) {
+    assert(logger);
+
+    if (logger->should_log(level_)) {
+      logger_ = logger;
+      // event_name_ = fmt::format(fmt, std::forward<Args>(args)...);
+      // Forwarding args in make_format_args causes an error.
+      event_name_ = fmt::vformat(fmt, fmt::make_format_args(args...));
+      logger_->log(level_, "{} started", event_name_);
+      start_ = std::chrono::high_resolution_clock::now();
+    }
+  }
+
+  ~LogDuration() {
+    if (logger_) {
+      auto end = std::chrono::high_resolution_clock::now();
+      std::chrono::duration<float, std::chrono::milliseconds::period> duration =
+          end - start_;
+      logger_->log(level_, "{} took {} ms", event_name_, duration.count());
+    }
+  }
+
+ private:
+  Logger::Level level_;
+  /**
+   * 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_;
+  std::chrono::time_point<std::chrono::high_resolution_clock> start_;
+  std::string event_name_;
+};
+
+}  // namespace tiledb::common
+
+#endif  // TILEDB_LOG_DURATION_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,45 @@ 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/c_api/tiledb_filestore.cc

@@ -88,6 +88,7 @@ int32_t tiledb_filestore_schema_create(
     // Get the file size, calculate a reasonable tile extent
     tiledb::sm::VFS vfs(
         &context.resources().stats(),
+        context.resources().logger().get(),
         context.compute_tp(),
         context.io_tp(),
         context.resources().config());
@@ -200,6 +201,7 @@ int32_t tiledb_filestore_uri_import(
   // Get the file size
   tiledb::sm::VFS vfs(
       &context.resources().stats(),
+      context.resources().logger().get(),
       context.compute_tp(),
       context.io_tp(),
       context.resources().config());
@@ -388,6 +390,7 @@ int32_t tiledb_filestore_uri_export(
   tiledb::sm::Context& context = ctx->context();
   tiledb::sm::VFS vfs(
       &context.resources().stats(),
+      context.resources().logger().get(),
       context.compute_tp(),
       context.io_tp(),
       context.resources().config());

tiledb/sm/config/config.cc

@@ -174,6 +174,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 = "";
@@ -402,6 +403,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,10 @@ 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 of the start and end of 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