From 11dcbf1950dd6c62542296d0107aca5561384e2f Mon Sep 17 00:00:00 2001 From: theanarkh Date: Thu, 20 Oct 2022 23:09:14 +0800 Subject: [PATCH] fs: trace more fs api --- src/node_dir.cc | 2 + src/node_file.cc | 17 ++++- test/parallel/test-trace-events-fs-handle.js | 72 ++++++++++++++++++++ 3 files changed, 89 insertions(+), 2 deletions(-) create mode 100644 test/parallel/test-trace-events-fs-handle.js diff --git a/src/node_dir.cc b/src/node_dir.cc index bc86f828b184cb..fc3b2beac720ed 100644 --- a/src/node_dir.cc +++ b/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; diff --git a/src/node_file.cc b/src/node_file.cc index 92274e934d995e..cdfcf5bac29c3a 100644 --- a/src/node_file.cc +++ b/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 FileHandle::ClosePromise() { CloseReq* req = new CloseReq(env(), close_req_obj, promise, object()); auto AfterClose = uv_fs_callback_t{[](uv_fs_t* req) { - BaseObjectPtr close(CloseReq::from_req(req)); + CloseReq* req_wrap = CloseReq::from_req(req); + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) + BaseObjectPtr close(req_wrap); CHECK(close); close->file_handle()->AfterClose(); if (!close->env()->can_call_into_js()) return; @@ -474,6 +481,7 @@ MaybeLocal 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_, ¤t_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(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(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::from_req(req)); + FS_ASYNC_TRACE_END1( + req->fs_type, wrap, "result", static_cast(req->result)) FileHandle* handle = static_cast(wrap->stream()); handle->AfterClose(); diff --git a/test/parallel/test-trace-events-fs-handle.js b/test/parallel/test-trace-events-fs-handle.js new file mode 100644 index 00000000000000..597a963350231e --- /dev/null +++ b/test/parallel/test-trace-events-fs-handle.js @@ -0,0 +1,72 @@ +'use strict'; +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& 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 { + filehandle = null; + } + } + // Call void DirHandle::GCClose() during gc + { + let dir = await opendir('.'); + dir = null; + } + gc(); + })(); + 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);