fs: trace more fs api

Author: theanarkh

src/node_dir.cc

@@ -135,7 +135,9 @@ void DirHandle::MemoryInfo(MemoryTracker* tracker) const {
 inline void DirHandle::GCClose() {
   if (closed_) return;
   uv_fs_t req;
+  FS_DIR_SYNC_TRACE_BEGIN(closedir);
   int ret = uv_fs_closedir(nullptr, &req, dir_, nullptr);
+  FS_DIR_SYNC_TRACE_END(closedir);
   uv_fs_req_cleanup(&req);
   closing_ = false;
   closed_ = true;

src/node_file.cc

@@ -302,7 +302,9 @@ FileHandle::TransferData::~TransferData() {
   if (fd_ > 0) {
     uv_fs_t close_req;
     CHECK_NE(fd_, -1);
+    FS_SYNC_TRACE_BEGIN(close);
     CHECK_EQ(0, uv_fs_close(nullptr, &close_req, fd_, nullptr));
+    FS_SYNC_TRACE_END(close);
     uv_fs_req_cleanup(&close_req);
   }
 }
@@ -327,7 +329,9 @@ inline void FileHandle::Close() {
   if (closed_ || closing_) return;
   uv_fs_t req;
   CHECK_NE(fd_, -1);
+  FS_SYNC_TRACE_BEGIN(close);
   int ret = uv_fs_close(env()->event_loop(), &req, fd_, nullptr);
+  FS_SYNC_TRACE_END(close);
   uv_fs_req_cleanup(&req);
 
   struct err_detail { int ret; int fd; };
@@ -460,7 +464,10 @@ MaybeLocal<Promise> FileHandle::ClosePromise() {
 
   CloseReq* req = new CloseReq(env(), close_req_obj, promise, object());
   auto AfterClose = uv_fs_callback_t{[](uv_fs_t* req) {
-    BaseObjectPtr<CloseReq> close(CloseReq::from_req(req));
+    CloseReq* req_wrap = CloseReq::from_req(req);
+    FS_ASYNC_TRACE_END1(
+        req->fs_type, req_wrap, "result", static_cast<int>(req->result))
+    BaseObjectPtr<CloseReq> close(req_wrap);
     CHECK(close);
     close->file_handle()->AfterClose();
     if (!close->env()->can_call_into_js()) return;
@@ -474,6 +481,7 @@ MaybeLocal<Promise> FileHandle::ClosePromise() {
     }
   }};
   CHECK_NE(fd_, -1);
+  FS_ASYNC_TRACE_BEGIN0(UV_FS_CLOSE, req)
   int ret = req->Dispatch(uv_fs_close, fd_, AfterClose);
   if (ret < 0) {
     req->Reject(UVException(isolate, ret, "close"));
@@ -569,7 +577,7 @@ int FileHandle::ReadStart() {
   read_wrap->buffer_ = EmitAlloc(recommended_read);
 
   current_read_ = std::move(read_wrap);
-
+  FS_ASYNC_TRACE_BEGIN0(UV_FS_READ, current_read_.get())
   current_read_->Dispatch(uv_fs_read,
                           fd_,
                           &current_read_->buffer_,
@@ -579,6 +587,8 @@ int FileHandle::ReadStart() {
     FileHandle* handle;
     {
       FileHandleReadWrap* req_wrap = FileHandleReadWrap::from_req(req);
+      FS_ASYNC_TRACE_END1(
+          req->fs_type, req_wrap, "result", static_cast<int>(req->result))
       handle = req_wrap->file_handle_;
       CHECK_EQ(handle->current_read_.get(), req_wrap);
     }
@@ -652,9 +662,12 @@ int FileHandle::DoShutdown(ShutdownWrap* req_wrap) {
   FileHandleCloseWrap* wrap = static_cast<FileHandleCloseWrap*>(req_wrap);
   closing_ = true;
   CHECK_NE(fd_, -1);
+  FS_ASYNC_TRACE_BEGIN0(UV_FS_CLOSE, wrap)
   wrap->Dispatch(uv_fs_close, fd_, uv_fs_callback_t{[](uv_fs_t* req) {
     FileHandleCloseWrap* wrap = static_cast<FileHandleCloseWrap*>(
         FileHandleCloseWrap::from_req(req));
+    FS_ASYNC_TRACE_END1(
+        req->fs_type, wrap, "result", static_cast<int>(req->result))
     FileHandle* handle = static_cast<FileHandle*>(wrap->stream());
     handle->AfterClose();
 

test/parallel/test-trace-events-fs-handle.js

@@ -0,0 +1,74 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+const path = require('path');
+
+if (process.env.isChild === '1') {
+  const { open, opendir } = require('fs/promises');
+  const trace_events = require('trace_events');
+  const tracing = trace_events.createTracing({ categories: ['node.fs.async', 'node.fs.sync', 'node.fs_dir.sync'] });
+  tracing.enable();
+  (async function test() {
+    // Call FileHandle::Close(const FunctionCallbackInfo<Value>& args)
+    {
+      let filehandle = null;
+      try {
+        filehandle = await open(__filename, 'r');
+      } finally {
+        await filehandle.close();
+      }
+    }
+    // Call void FileHandle::Close() during gc
+    {
+      let filehandle = null;
+      try {
+        filehandle = await open(__filename, 'r');
+      } finally {
+        // eslint-disable-next-line no-unused-vars
+        filehandle = null;
+      }
+    }
+    // Call void DirHandle::GCClose() during gc
+    {
+      let dir = await opendir('.');
+      // eslint-disable-next-line no-unused-vars
+      dir = null;
+    }
+    global.gc();
+  })().then(common.mustCall());
+  return;
+}
+
+const tmpdir = require('../common/tmpdir');
+tmpdir.refresh();
+const traceFile = path.join(tmpdir.path, 'node_trace.1.log');
+
+cp.spawnSync(process.execPath,
+             ['--expose-gc', __filename],
+             { cwd: tmpdir.path, encoding: 'utf8', env: { ...process.env, isChild: '1' } });
+
+assert(fs.existsSync(traceFile));
+const data = fs.readFileSync(traceFile);
+const traces = JSON.parse(data.toString()).traceEvents;
+assert(traces.length > 0);
+
+let syncClose = 0;
+let asyncClose = 0;
+let syncCloseDir = 0;
+
+traces.forEach((trace) => {
+  if (trace.cat === 'node,node.fs,node.fs.sync' && trace.name === 'fs.sync.close') {
+    syncClose++;
+  } else if (trace.cat === 'node,node.fs,node.fs.async' && trace.name === 'close') {
+    asyncClose++;
+  } else if (trace.cat === 'node,node.fs_dir,node.fs_dir.sync' && trace.name === 'fs_dir.sync.closedir') {
+    syncCloseDir++;
+  }
+});
+
+// One begin event, one end event
+assert.strictEqual(syncClose, 2);
+assert.strictEqual(asyncClose, 2);
+assert.strictEqual(syncCloseDir, 2);