From ec27eb3ff50f46ba0bf5502d5774892299c065be Mon Sep 17 00:00:00 2001
From: shirady <57721533+shirady@users.noreply.github.com>
Date: Tue, 17 Dec 2024 12:40:42 +0200
Subject: [PATCH 1/2] NC | NSFS | Add logging printing measuring tome duration

Signed-off-by: shirady <57721533+shirady@users.noreply.github.com>
---
 src/native/fs/fs_napi.cpp | 5 +++++
 src/util/buffer_utils.js  | 3 +++
 2 files changed, 8 insertions(+)

diff --git a/src/native/fs/fs_napi.cpp b/src/native/fs/fs_napi.cpp
index af7bfcf137..5a5418c177 100644
--- a/src/native/fs/fs_napi.cpp
+++ b/src/native/fs/fs_napi.cpp
@@ -2240,9 +2240,14 @@ register_gpfs_noobaa(const Napi::CallbackInfo& info)
 static Napi::Value
 dio_buffer_alloc(const Napi::CallbackInfo& info)
 {
+    auto start_time = std::chrono::high_resolution_clock::now();
+    double _took_time;
     int size = info[0].As<Napi::Number>();
     uint8_t* buf = 0;
     int r = posix_memalign((void**)&buf, DIO_BUFFER_MEMALIGN, size);
+    auto end_time = std::chrono::high_resolution_clock::now();
+    _took_time = std::chrono::duration<double, std::milli>(end_time - start_time).count();
+    DBG2("dio_buffer_alloc took: " << _took_time << " ms");
     if (r || (!buf && size > 0)) {
         throw Napi::Error::New(info.Env(), "FS::dio_buffer_alloc: failed to allocate memory");
     }
diff --git a/src/util/buffer_utils.js b/src/util/buffer_utils.js
index 25576a03ae..5b46f29d73 100644
--- a/src/util/buffer_utils.js
+++ b/src/util/buffer_utils.js
@@ -212,7 +212,10 @@ class BuffersPool {
         if (this.buffers.length) {
             buffer = this.buffers.shift();
         } else {
+            const start = performance.now();
             buffer = this.buffer_alloc(this.buf_size);
+            const end = performance.now();
+            dbg.log2(`get_buffer: Time taken to execute buffer_alloc function with buf_size ${this.buf_size} is ${end - start} ms.`);
         }
         if (this.warning_timeout) {
             const err = new Error('Warning stuck buffer_pool buffer');

From 150c709f91d441a06211ff1c0ece9f44b242c39a Mon Sep 17 00:00:00 2001
From: shirady <57721533+shirady@users.noreply.github.com>
Date: Sun, 22 Dec 2024 13:41:34 +0200
Subject: [PATCH 2/2] also print duration in the callaback execution

Signed-off-by: shirady <57721533+shirady@users.noreply.github.com>
---
 src/sdk/namespace_fs.js | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/src/sdk/namespace_fs.js b/src/sdk/namespace_fs.js
index fabe042ed3..f5abe59268 100644
--- a/src/sdk/namespace_fs.js
+++ b/src/sdk/namespace_fs.js
@@ -1086,7 +1086,10 @@ class NamespaceFS {
                 const bytesRead = await file.read(fs_context, buffer, 0, read_size, pos);
                 if (!bytesRead) {
                     buffer_pool_cleanup = null;
+                    const start_time = performance.now();
                     callback();
+                    const end_time = performance.now();
+                    dbg.log2(`get_buffer: Time taken to execute callback is ${end_time - start_time} ms.`);
                     break;
                 }
                 object_sdk.throw_if_aborted();
@@ -1111,15 +1114,22 @@ class NamespaceFS {
 
                 // wait for response buffer to drain before adding more data if needed -
                 // this occurs when the output network is slower than the input file
+                const start_time_drain_promise = performance.now();
                 if (drain_promise) {
+                    dbg.log2('iniside condition: drain_promise');
                     await drain_promise;
                     drain_promise = null;
                     object_sdk.throw_if_aborted();
                 }
+                const end_time_drain_promise = performance.now();
+                dbg.log2(`drain_promise: Time taken to execute is ${end_time_drain_promise - start_time_drain_promise} ms.`);
 
                 // write the data out to response
                 buffer_pool_cleanup = null; // cleanup is now in the socket responsibility
+                const start_time_write = performance.now();
                 const write_ok = res.write(data, null, callback);
+                const end_time_write = performance.now();
+                dbg.log2(`write to socket: Time taken to execute is ${end_time_write - start_time_write} ms.`);
                 if (!write_ok) {
                     drain_promise = stream_utils.wait_drain(res, { signal: object_sdk.abort_controller.signal });
                     drain_promise.catch(() => undefined); // this avoids UnhandledPromiseRejection
@@ -1132,6 +1142,7 @@ class NamespaceFS {
 
             // wait for the last drain if pending.
             if (drain_promise) {
+                dbg.log2('iniside condition2 (last drain): drain_promise');
                 await drain_promise;
                 drain_promise = null;
                 object_sdk.throw_if_aborted();