include/client/preload.hpp

@@ -46,6 +46,7 @@
 #define EUNKNOWN (-1)
 
 #define CTX gkfs::preload::PreloadContext::getInstance()
+#define DT gkfs::preload::DebugTimer::getInstance()
 namespace gkfs::preload {
 void
 init_environment();

include/client/preload_context.hpp

@@ -50,6 +50,14 @@
 
 #include <bitset>
 
+// Debug timer
+#include <chrono>
+#include <unordered_map>
+#include <string>
+#include <mutex>
+extern char *program_invocation_name;
+// ---------
+
 /* Forward declarations */
 namespace gkfs {
 namespace filemap {
@@ -75,6 +83,43 @@ class WriteSizeCache;
 } // namespace cache
 
 namespace preload {
+
+// Debug timer
+class DebugTimer {
+public:
+    static DebugTimer&
+    getInstance() {
+        static DebugTimer instance;
+        return instance;
+    }
+
+    void
+    record(const std::string& name);
+
+    void
+    write_stats(const std::string& file);
+
+private:
+    struct Stat {
+        std::chrono::high_resolution_clock::time_point lastTime{};
+        int callCount = 0;
+        double maxDuration = 0.0;
+        double totalDuration = 0.0;
+    };
+
+    std::chrono::high_resolution_clock::time_point start_time{};
+    std::unordered_map<std::string, Stat> stats_;
+    mutable std::mutex mutex_;
+
+    // Private constructor to enforce singleton
+    DebugTimer();
+    ~DebugTimer() = default;
+    DebugTimer(const DebugTimer&) = delete;
+    DebugTimer&
+    operator=(const DebugTimer&) = delete;
+};
+// ---------
+
 /*
  * Client file system config
  */

src/client/gkfs_libc.cpp

@@ -580,7 +580,9 @@ is_gkfs_fd(int fd) {
 #define GKFS_OPERATION(name, ...)                                              \
     if(CTX->interception_enabled() && is_gkfs_fd(fd)) {                        \
                                                                                \
+        DT.record(#name);                                                      \
         auto res = gkfs::syscall::gkfs_##name(__VA_ARGS__);                    \
+        DT.record(#name);                                                      \
         DEBUG_INFO("[GKFS] {} -> res {}", fd, res);                            \
         return res;                                                            \
     }
@@ -589,9 +591,13 @@ is_gkfs_fd(int fd) {
     if(CTX->interception_enabled()) {                                          \
         std::string resolved;                                                  \
         switch(resolve_gkfs_path(dirfd, path, resolved)) {                     \
-            case PathStatus::Internal:                                         \
+            case PathStatus::Internal: {                                       \
                 DEBUG_INFO("[GKFS] {}", resolved);                             \
-                return gkfs::syscall::gkfs_##name(resolved, __VA_ARGS__);      \
+                DT.record(#name);                                              \
+                auto res = gkfs::syscall::gkfs_##name(resolved, __VA_ARGS__);  \
+                DT.record(#name);                                              \
+                return res;                                                    \
+            }                                                                  \
             case PathStatus::Error:                                            \
                 return -1;                                                     \
             default:                                                           \
@@ -603,10 +609,14 @@ is_gkfs_fd(int fd) {
     if(CTX->interception_enabled()) {                                          \
         std::string resolved;                                                  \
         switch(resolve_gkfs_path(dirfd, path, resolved)) {                     \
-            case PathStatus::Internal:                                         \
+            case PathStatus::Internal: {                                       \
                 DEBUG_INFO("[GKFS] {}", resolved);                             \
-                return gkfs::syscall::gkfs_##name(dirfd, resolved,             \
+                DT.record(#name);                                              \
+                auto res = gkfs::syscall::gkfs_##name(dirfd, resolved,         \
                                                       __VA_ARGS__);            \
+                DT.record(#name);                                              \
+                return res;                                                    \
+            }                                                                  \
             case PathStatus::Error:                                            \
                 return -1;                                                     \
             default:                                                           \
@@ -618,9 +628,13 @@ is_gkfs_fd(int fd) {
     if(CTX->interception_enabled()) {                                          \
         std::string resolved;                                                  \
         switch(resolve_gkfs_path(dirfd, path, resolved)) {                     \
-            case PathStatus::Internal:                                         \
+            case PathStatus::Internal: {                                       \
                 DEBUG_INFO("[GKFS] {}", resolved);                             \
-                return gkfs::syscall::gkfs_##name(resolved);                   \
+                DT.record(#name);                                              \
+                auto res = gkfs::syscall::gkfs_##name(resolved);               \
+                DT.record(#name);                                              \
+                return res;                                                    \
+            }                                                                  \
             case PathStatus::Error:                                            \
                 return -1;                                                     \
             default:                                                           \
@@ -936,7 +950,9 @@ __xstat64(int ver, const char* path, struct stat64* buf) {
         switch(resolve_gkfs_path(AT_FDCWD, path, resolved)) {
             case PathStatus::Internal: {
                 DEBUG_INFO("[GKFS] {}", resolved);
+                DT.record("__xstat64");
                 auto res = gkfs::syscall::gkfs_stat(resolved, &st);
+                DT.record("__xstat64");
                 convert(&st, buf);
                 return res;
             }
@@ -980,7 +996,9 @@ __lxstat(int ver, const char* path, struct stat* buf) {
         switch(resolve_gkfs_path(AT_FDCWD, path, resolved, 0, false)) {
             case PathStatus::Internal: {
                 DEBUG_INFO("[GKFS] {}", resolved);
+                DT.record("__lxstat");
                 auto res = gkfs::syscall::gkfs_stat(resolved, buf, false);
+                DT.record("__lxstat");
                 return res;
             }
             case PathStatus::Error: {
@@ -1003,7 +1021,9 @@ __lxstat64(int ver, const char* path, struct stat64* buf) {
         switch(resolve_gkfs_path(AT_FDCWD, path, resolved)) {
             case PathStatus::Internal: {
                 DEBUG_INFO("[GKFS] {}", resolved);
+                DT.record("__lxstat64");
                 auto res = gkfs::syscall::gkfs_stat(resolved, &st, false);
+                DT.record("__lxstat64");
                 convert(&st, buf);
                 return res;
             }
@@ -1042,8 +1062,10 @@ __fxstat64(int ver, int fd, struct stat64* buf) {
     if(CTX->interception_enabled() && is_gkfs_fd(fd)) {
         struct stat st;
         DEBUG_INFO("[GKFS] {}", CTX->file_map()->get(fd)->path());
+        DT.record("__fxstat64");
         int res = gkfs::syscall::gkfs_stat(CTX->file_map()->get(fd)->path(),
                                            &st, true, true);
+        DT.record("__fxstat64");
         if(res == 0)
             convert(&st, buf);
         return res;
@@ -1057,8 +1079,10 @@ fstat64(int fd, struct stat64* buf) {
     if(CTX->interception_enabled() && is_gkfs_fd(fd)) {
         struct stat st;
         DEBUG_INFO("[GKFS] {}", CTX->file_map()->get(fd)->path());
+        DT.record("fstat64");
         int res = gkfs::syscall::gkfs_stat(CTX->file_map()->get(fd)->path(),
                                            &st, true, true);
+        DT.record("fstat64");
         if(res == 0)
             convert(&st, buf);
         return res;
@@ -1074,8 +1098,10 @@ fstat(int fd, struct stat* buf) {
 
         // The fd could be a renamed file, thus when doing gkfs_stat we will get
         // a is not found.
+        DT.record("fstat");
         int res = gkfs::syscall::gkfs_stat(CTX->file_map()->get(fd)->path(),
                                            buf, true, true);
+        DT.record("fstat");
         return res;
     }
     GKFS_FALLBACK(fstat, fd, buf);
@@ -1092,8 +1118,10 @@ __fxstatat64(int ver, int dfd, const char* path, struct stat64* buf,
             case PathStatus::Internal: {
                 DEBUG_INFO("[GKFS] {}", resolved);
                 bool follow = (flags & AT_SYMLINK_NOFOLLOW) == 0;
+                DT.record("__fxstatat64");
                 auto res = gkfs::syscall::gkfs_stat(resolved, &st, follow);
                 convert(&st, buf);
+                DT.record("__fxstatat64");
                 return res;
             }
             case PathStatus::Error: {
@@ -1122,8 +1150,10 @@ stat64(const char* path, struct stat64* buf) {
         switch(resolve_gkfs_path(AT_FDCWD, path, resolved)) {
             case PathStatus::Internal: {
                 DEBUG_INFO("[GKFS] {}", resolved);
+                DT.record("stat64");
                 auto res = gkfs::syscall::gkfs_stat(resolved, &st);
                 convert(&st, buf);
+                DT.record("stat64");
                 return res;
             }
             case PathStatus::Error: {
@@ -1148,7 +1178,9 @@ fstatat(int dfd, const char* path, struct stat* buf, int flags) {
             case PathStatus::Internal: {
                 DEBUG_INFO("[GKFS] {}", resolved);
                 bool follow = (flags & AT_SYMLINK_NOFOLLOW) == 0;
+                DT.record("fstatat");
                 auto res = gkfs::syscall::gkfs_stat(resolved, buf, follow);
+                DT.record("fstatat");
                 return res;
             }
             case PathStatus::Error: {

src/client/preload.cpp

@@ -96,6 +96,7 @@ exit_error_msg(int errcode, const string& msg) {
 bool
 init_hermes_client() {
 
+    DT.record("init_hermes_client");
     try {
 
         hermes::engine_options opts{};
@@ -130,6 +131,7 @@ init_hermes_client() {
             return false;
         }
     }
+    DT.record("init_hermes_client");
 
     return true;
 }
@@ -209,6 +211,7 @@ namespace gkfs::preload {
 void
 init_environment() {
 
+    DT.record("init_environment");
     vector<pair<string, string>> hosts{};
     try {
         LOG(INFO, "Loading peer addresses...");
@@ -353,6 +356,7 @@ init_environment() {
         srand(time(nullptr));
     }
 
+    DT.record("init_environment");
     LOG(INFO, "Environment initialization successful.");
 }
 
@@ -369,6 +373,7 @@ void
 init_preload() {
     // The original errno value will be restored after initialization to not
     // leak internal error codes
+    DT.record("init_preload");
     auto oerrno = errno;
     if(atomic_exchange(&init, 1) == 0) {
         pthread_atfork(&at_fork_syscall, &at_parent_syscall, &at_child_syscall);
@@ -415,6 +420,7 @@ init_preload() {
     if(!forwarding_map_file.empty()) {
         init_forwarding_mapper();
     }
+    DT.record("init_preload");
 
     gkfs::preload::start_interception();
     errno = oerrno;
@@ -430,6 +436,7 @@ init_preload() {
  */
 void
 destroy_preload() {
+    DT.record("destroy_preload");
     auto forwarding_map_file = gkfs::env::get_var(
             gkfs::env::FORWARDING_MAP_FILE, gkfs::config::forwarding_file_path);
     if(!forwarding_map_file.empty()) {
@@ -461,6 +468,8 @@ destroy_preload() {
         LOG(DEBUG, "Syscall interception stopped");
     }
 
+    DT.record("destroy_preload");
+    DT.write_stats("/tmp/gkfs_stats.txt");
     LOG(INFO, "All subsystems shut down. Client shutdown complete.");
 }
 
@@ -471,6 +480,7 @@ destroy_preload() {
  */
 extern "C" int
 gkfs_init() {
+    DT.record("gkfs_init");
     CTX->init_logging();
     // from here ownwards it is safe to print messages
     LOG(DEBUG, "Logging subsystem initialized");
@@ -488,6 +498,7 @@ gkfs_init() {
     if(CTX->protect_fds())
         CTX->unprotect_user_fds();
 
+    DT.record("gkfs_init");
     return 0;
 }
 
@@ -543,6 +554,7 @@ init_libc() {
 
 void
 destroy_libc() {
+    DT.write_stats("/tmp/gkfs_libc_stats.txt");
     CTX->disable_interception();
 #ifdef GKFS_ENABLE_CLIENT_METRICS
     LOG(INFO, "Flushing final metrics...");

src/client/preload_context.cpp

@@ -71,6 +71,62 @@ namespace gkfs {
 
 namespace preload {
 
+DebugTimer::DebugTimer() {
+    this->start_time = std::chrono::high_resolution_clock::now();
+    LOG(DEBUG, "Create DebugTimer");
+}
+
+// Debug timer
+void
+DebugTimer::record(const std::string& name) {
+    std::lock_guard<std::mutex> lock(mutex_);
+
+    auto now = std::chrono::high_resolution_clock::now();
+    auto& stat = stats_[name];
+
+    if(stat.lastTime.time_since_epoch().count() != 0) {
+        auto duration =
+                std::chrono::duration<double, std::milli>(now - stat.lastTime)
+                        .count();
+        stat.callCount++;
+        if(duration > stat.maxDuration)
+            stat.maxDuration = duration;
+        stat.totalDuration += duration;
+    }
+
+    stat.lastTime = now;
+}
+
+void
+DebugTimer::write_stats(const std::string& file) {
+    LOG(DEBUG, "Write DebugTimer stats");
+    std::lock_guard<std::mutex> lock(mutex_);
+
+    std::ofstream myfile(file, std::ios_base::app);
+
+    auto now = std::chrono::high_resolution_clock::now();
+    auto duration =
+            std::chrono::duration<double, std::milli>(now - this->start_time)
+                    .count();
+
+    if(myfile.is_open()) {
+        myfile << "-----" << program_invocation_name << "-----" << std::endl;
+        myfile << "timestamp: " << now.time_since_epoch().count() << std::endl;
+        myfile << "duration: " << duration << "ms" << std::endl << std::endl;
+        for(const auto& [name, stat] : stats_) {
+            myfile << "Name: " << name << "\n  Calls: " << stat.callCount
+                   << "\n  Max duration: " << stat.maxDuration << " ms"
+                   << "\n  Avg duration: "
+                   << (stat.callCount ? stat.totalDuration / stat.callCount : 0)
+                   << " ms\n";
+        }
+        myfile.close();
+    } else {
+        LOG(DEBUG, "could not write stats o.0");
+    }
+}
+// ---------
+
 decltype(PreloadContext::MIN_INTERNAL_FD) constexpr PreloadContext::
         MIN_INTERNAL_FD;
 decltype(PreloadContext::MAX_USER_FDS) constexpr PreloadContext::MAX_USER_FDS;