From 7fc110e429224d915d4729b0a3509dd450fc8d7b Mon Sep 17 00:00:00 2001 From: theanarkh Date: Sun, 31 Jul 2022 01:45:51 +0800 Subject: [PATCH] src: trace fs async api --- doc/api/tracing.md | 5 + src/node_dir.cc | 64 +++- src/node_file.cc | 202 ++++++++++-- test/parallel/test-trace-events-fs-async.js | 341 ++++++++++++++++++++ 4 files changed, 585 insertions(+), 27 deletions(-) create mode 100644 test/parallel/test-trace-events-fs-async.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index 7766412ed0b75a..a45f29f1792214 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -26,6 +26,11 @@ The available categories are: * `node.net.native`: Enables capture of trace data for network. * `node.environment`: Enables capture of Node.js Environment milestones. * `node.fs.sync`: Enables capture of trace data for file system sync methods. +* `node.fs_dir.sync`: Enables capture of trace data for file system sync + directory methods. +* `node.fs.async`: Enables capture of trace data for file system async methods. +* `node.fs_dir.async`: Enables capture of trace data for file system async + directory methods. * `node.perf`: Enables capture of [Performance API][] measurements. * `node.perf.usertiming`: Enables capture of only Performance API User Timing measures and marks. diff --git a/src/node_dir.cc b/src/node_dir.cc index c530da0cc3be4b..3a111fdabd3c9b 100644 --- a/src/node_dir.cc +++ b/src/node_dir.cc @@ -42,18 +42,57 @@ using v8::Object; using v8::ObjectTemplate; using v8::Value; +static const char* get_dir_func_name_by_type(uv_fs_type req_type) { + switch (req_type) { +#define FS_TYPE_TO_NAME(type, name) \ + case UV_FS_##type: \ + return name; + FS_TYPE_TO_NAME(OPENDIR, "opendir") + FS_TYPE_TO_NAME(READDIR, "readdir") + FS_TYPE_TO_NAME(CLOSEDIR, "closedir") +#undef FS_TYPE_TO_NAME + default: + return "unknow"; + } +} + #define TRACE_NAME(name) "fs_dir.sync." #name #define GET_TRACE_ENABLED \ - (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED \ - (TRACING_CATEGORY_NODE2(fs_dir, sync)) != 0) + (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( \ + TRACING_CATEGORY_NODE2(fs_dir, sync)) != 0) #define FS_DIR_SYNC_TRACE_BEGIN(syscall, ...) \ if (GET_TRACE_ENABLED) \ - TRACE_EVENT_BEGIN(TRACING_CATEGORY_NODE2(fs_dir, sync), TRACE_NAME(syscall), \ - ##__VA_ARGS__); + TRACE_EVENT_BEGIN(TRACING_CATEGORY_NODE2(fs_dir, sync), \ + TRACE_NAME(syscall), \ + ##__VA_ARGS__); #define FS_DIR_SYNC_TRACE_END(syscall, ...) \ if (GET_TRACE_ENABLED) \ - TRACE_EVENT_END(TRACING_CATEGORY_NODE2(fs_dir, sync), TRACE_NAME(syscall), \ - ##__VA_ARGS__); + TRACE_EVENT_END(TRACING_CATEGORY_NODE2(fs_dir, sync), \ + TRACE_NAME(syscall), \ + ##__VA_ARGS__); + +#define FS_DIR_ASYNC_TRACE_BEGIN0(fs_type, id) \ + TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(TRACING_CATEGORY_NODE2(fs_dir, async), \ + get_dir_func_name_by_type(fs_type), \ + id); +#define FS_DIR_ASYNC_TRACE_END0(fs_type, id) \ + TRACE_EVENT_NESTABLE_ASYNC_END0(TRACING_CATEGORY_NODE2(fs_dir, async), \ + get_dir_func_name_by_type(fs_type), \ + id); + +#define FS_DIR_ASYNC_TRACE_BEGIN1(fs_type, id, name, value) \ + TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(TRACING_CATEGORY_NODE2(fs_dir, async), \ + get_dir_func_name_by_type(fs_type), \ + id, \ + name, \ + value); + +#define FS_DIR_ASYNC_TRACE_END1(fs_type, id, name, value) \ + TRACE_EVENT_NESTABLE_ASYNC_END1(TRACING_CATEGORY_NODE2(fs_dir, async), \ + get_dir_func_name_by_type(fs_type), \ + id, \ + name, \ + value); DirHandle::DirHandle(Environment* env, Local obj, uv_dir_t* dir) : AsyncWrap(env, obj, AsyncWrap::PROVIDER_DIRHANDLE), @@ -132,7 +171,8 @@ inline void DirHandle::GCClose() { void AfterClose(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_DIR_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) if (after.Proceed()) req_wrap->Resolve(Undefined(req_wrap->env()->isolate())); } @@ -151,6 +191,7 @@ void DirHandle::Close(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 0); if (req_wrap_async != nullptr) { // close(req) + FS_DIR_ASYNC_TRACE_BEGIN0(UV_FS_CLOSEDIR, req_wrap_async) AsyncCall(env, req_wrap_async, args, "closedir", UTF8, AfterClose, uv_fs_closedir, dir->dir()); } else { // close(undefined, ctx) @@ -196,7 +237,8 @@ static MaybeLocal DirentListToArray( static void AfterDirRead(uv_fs_t* req) { BaseObjectPtr req_wrap { FSReqBase::from_req(req) }; FSReqAfterScope after(req_wrap.get(), req); - + FS_DIR_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) if (!after.Proceed()) { return; } @@ -256,6 +298,7 @@ void DirHandle::Read(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // dir.read(encoding, bufferSize, req) + FS_DIR_ASYNC_TRACE_BEGIN0(UV_FS_READDIR, req_wrap_async) AsyncCall(env, req_wrap_async, args, "readdir", encoding, AfterDirRead, uv_fs_readdir, dir->dir()); } else { // dir.read(encoding, bufferSize, undefined, ctx) @@ -298,7 +341,8 @@ void DirHandle::Read(const FunctionCallbackInfo& args) { void AfterOpenDir(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_DIR_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) if (!after.Proceed()) { return; } @@ -325,6 +369,8 @@ static void OpenDir(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // openDir(path, encoding, req) + FS_DIR_ASYNC_TRACE_BEGIN1( + UV_FS_OPENDIR, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "opendir", encoding, AfterOpenDir, uv_fs_opendir, *path); } else { // openDir(path, encoding, undefined, ctx) diff --git a/src/node_file.cc b/src/node_file.cc index a010479cd71c56..1ac6722d7aea18 100644 --- a/src/node_file.cc +++ b/src/node_file.cc @@ -111,18 +111,104 @@ inline int64_t GetOffset(Local value) { return IsSafeJsInt(value) ? value.As()->Value() : -1; } +static const char* get_fs_func_name_by_type(uv_fs_type req_type) { + switch (req_type) { +#define FS_TYPE_TO_NAME(type, name) \ + case UV_FS_##type: \ + return name; + FS_TYPE_TO_NAME(OPEN, "open") + FS_TYPE_TO_NAME(CLOSE, "close") + FS_TYPE_TO_NAME(READ, "read") + FS_TYPE_TO_NAME(WRITE, "write") + FS_TYPE_TO_NAME(SENDFILE, "sendfile") + FS_TYPE_TO_NAME(STAT, "stat") + FS_TYPE_TO_NAME(LSTAT, "lstat") + FS_TYPE_TO_NAME(FSTAT, "fstat") + FS_TYPE_TO_NAME(FTRUNCATE, "ftruncate") + FS_TYPE_TO_NAME(UTIME, "utime") + FS_TYPE_TO_NAME(FUTIME, "futime") + FS_TYPE_TO_NAME(ACCESS, "access") + FS_TYPE_TO_NAME(CHMOD, "chmod") + FS_TYPE_TO_NAME(FCHMOD, "fchmod") + FS_TYPE_TO_NAME(FSYNC, "fsync") + FS_TYPE_TO_NAME(FDATASYNC, "fdatasync") + FS_TYPE_TO_NAME(UNLINK, "unlink") + FS_TYPE_TO_NAME(RMDIR, "rmdir") + FS_TYPE_TO_NAME(MKDIR, "mkdir") + FS_TYPE_TO_NAME(MKDTEMP, "mkdtemp") + FS_TYPE_TO_NAME(RENAME, "rename") + FS_TYPE_TO_NAME(SCANDIR, "scandir") + FS_TYPE_TO_NAME(LINK, "link") + FS_TYPE_TO_NAME(SYMLINK, "symlink") + FS_TYPE_TO_NAME(READLINK, "readlink") + FS_TYPE_TO_NAME(CHOWN, "chown") + FS_TYPE_TO_NAME(FCHOWN, "fchown") + FS_TYPE_TO_NAME(REALPATH, "realpath") + FS_TYPE_TO_NAME(COPYFILE, "copyfile") + FS_TYPE_TO_NAME(LCHOWN, "lchown") + FS_TYPE_TO_NAME(STATFS, "statfs") + FS_TYPE_TO_NAME(MKSTEMP, "mkstemp") + FS_TYPE_TO_NAME(LUTIME, "lutime") +#undef FS_TYPE_TO_NAME + default: + return "unknow"; + } +} + #define TRACE_NAME(name) "fs.sync." #name -#define GET_TRACE_ENABLED \ - (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED \ - (TRACING_CATEGORY_NODE2(fs, sync)) != 0) -#define FS_SYNC_TRACE_BEGIN(syscall, ...) \ - if (GET_TRACE_ENABLED) \ - TRACE_EVENT_BEGIN(TRACING_CATEGORY_NODE2(fs, sync), TRACE_NAME(syscall), \ - ##__VA_ARGS__); -#define FS_SYNC_TRACE_END(syscall, ...) \ - if (GET_TRACE_ENABLED) \ - TRACE_EVENT_END(TRACING_CATEGORY_NODE2(fs, sync), TRACE_NAME(syscall), \ - ##__VA_ARGS__); +#define GET_TRACE_ENABLED \ + (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( \ + TRACING_CATEGORY_NODE2(fs, sync)) != 0) +#define FS_SYNC_TRACE_BEGIN(syscall, ...) \ + if (GET_TRACE_ENABLED) \ + TRACE_EVENT_BEGIN( \ + TRACING_CATEGORY_NODE2(fs, sync), TRACE_NAME(syscall), ##__VA_ARGS__); +#define FS_SYNC_TRACE_END(syscall, ...) \ + if (GET_TRACE_ENABLED) \ + TRACE_EVENT_END( \ + TRACING_CATEGORY_NODE2(fs, sync), TRACE_NAME(syscall), ##__VA_ARGS__); + +#define FS_ASYNC_TRACE_BEGIN0(fs_type, id) \ + TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(TRACING_CATEGORY_NODE2(fs, async), \ + get_fs_func_name_by_type(fs_type), \ + id); + +#define FS_ASYNC_TRACE_END0(fs_type, id) \ + TRACE_EVENT_NESTABLE_ASYNC_END0(TRACING_CATEGORY_NODE2(fs, async), \ + get_fs_func_name_by_type(fs_type), \ + id); + +#define FS_ASYNC_TRACE_BEGIN1(fs_type, id, name, value) \ + TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(TRACING_CATEGORY_NODE2(fs, async), \ + get_fs_func_name_by_type(fs_type), \ + id, \ + name, \ + value); + +#define FS_ASYNC_TRACE_END1(fs_type, id, name, value) \ + TRACE_EVENT_NESTABLE_ASYNC_END1(TRACING_CATEGORY_NODE2(fs, async), \ + get_fs_func_name_by_type(fs_type), \ + id, \ + name, \ + value); + +#define FS_ASYNC_TRACE_BEGIN2(fs_type, id, name1, value1, name2, value2) \ + TRACE_EVENT_NESTABLE_ASYNC_BEGIN2(TRACING_CATEGORY_NODE2(fs, async), \ + get_fs_func_name_by_type(fs_type), \ + id, \ + name1, \ + value1, \ + name2, \ + value2); + +#define FS_ASYNC_TRACE_END2(fs_type, id, name1, value1, name2, value2) \ + TRACE_EVENT_NESTABLE_ASYNC_END2(TRACING_CATEGORY_NODE2(fs, async), \ + get_fs_func_name_by_type(fs_type), \ + id, \ + name1, \ + value1, \ + name2, \ + value2); // We sometimes need to convert a C++ lambda function to a raw C-style function. // This is helpful, because ReqWrap::Dispatch() does not recognize lambda @@ -665,7 +751,8 @@ bool FSReqAfterScope::Proceed() { void AfterNoArgs(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) if (after.Proceed()) req_wrap->Resolve(Undefined(req_wrap->env()->isolate())); } @@ -673,7 +760,8 @@ void AfterNoArgs(uv_fs_t* req) { void AfterStat(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) if (after.Proceed()) { req_wrap->ResolveStat(&req->statbuf); } @@ -682,7 +770,8 @@ void AfterStat(uv_fs_t* req) { void AfterInteger(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) int result = static_cast(req->result); if (result >= 0 && req_wrap->is_plain_open()) req_wrap->env()->AddUnmanagedFd(result); @@ -694,7 +783,8 @@ void AfterInteger(uv_fs_t* req) { void AfterOpenFileHandle(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) if (after.Proceed()) { FileHandle* fd = FileHandle::New(req_wrap->binding_data(), static_cast(req->result)); @@ -719,6 +809,8 @@ void FromNamespacedPath(std::string* path) { void AfterMkdirp(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) if (after.Proceed()) { std::string first_path(req_wrap->continuation_data()->first_path()); if (first_path.empty()) @@ -738,7 +830,8 @@ void AfterMkdirp(uv_fs_t* req) { void AfterStringPath(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) MaybeLocal link; Local error; @@ -757,7 +850,8 @@ void AfterStringPath(uv_fs_t* req) { void AfterStringPtr(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) MaybeLocal link; Local error; @@ -776,7 +870,8 @@ void AfterStringPtr(uv_fs_t* req) { void AfterScanDir(uv_fs_t* req) { FSReqBase* req_wrap = FSReqBase::from_req(req); FSReqAfterScope after(req_wrap, req); - + FS_ASYNC_TRACE_END1( + req->fs_type, req_wrap, "result", static_cast(req->result)) if (!after.Proceed()) { return; } @@ -837,6 +932,8 @@ void Access(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // access(path, mode, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_ACCESS, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "access", UTF8, AfterNoArgs, uv_fs_access, *path, mode); } else { // access(path, mode, undefined, ctx) @@ -861,6 +958,7 @@ void Close(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 1); if (req_wrap_async != nullptr) { // close(fd, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_CLOSE, req_wrap_async) AsyncCall(env, req_wrap_async, args, "close", UTF8, AfterNoArgs, uv_fs_close, fd); } else { // close(fd, undefined, ctx) @@ -1002,6 +1100,8 @@ static void Stat(const FunctionCallbackInfo& args) { bool use_bigint = args[1]->IsTrue(); FSReqBase* req_wrap_async = GetReqWrap(args, 2, use_bigint); if (req_wrap_async != nullptr) { // stat(path, use_bigint, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_STAT, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "stat", UTF8, AfterStat, uv_fs_stat, *path); } else { // stat(path, use_bigint, undefined, ctx) @@ -1033,6 +1133,8 @@ static void LStat(const FunctionCallbackInfo& args) { bool use_bigint = args[1]->IsTrue(); FSReqBase* req_wrap_async = GetReqWrap(args, 2, use_bigint); if (req_wrap_async != nullptr) { // lstat(path, use_bigint, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_LSTAT, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "lstat", UTF8, AfterStat, uv_fs_lstat, *path); } else { // lstat(path, use_bigint, undefined, ctx) @@ -1065,6 +1167,7 @@ static void FStat(const FunctionCallbackInfo& args) { bool use_bigint = args[1]->IsTrue(); FSReqBase* req_wrap_async = GetReqWrap(args, 2, use_bigint); if (req_wrap_async != nullptr) { // fstat(fd, use_bigint, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_FSTAT, req_wrap_async) AsyncCall(env, req_wrap_async, args, "fstat", UTF8, AfterStat, uv_fs_fstat, fd); } else { // fstat(fd, use_bigint, undefined, ctx) @@ -1100,6 +1203,12 @@ static void Symlink(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // symlink(target, path, flags, req) + FS_ASYNC_TRACE_BEGIN2(UV_FS_SYMLINK, + req_wrap_async, + "target", + TRACE_STR_COPY(*target), + "path", + TRACE_STR_COPY(*path)) AsyncDestCall(env, req_wrap_async, args, "symlink", *path, path.length(), UTF8, AfterNoArgs, uv_fs_symlink, *target, *path, flags); } else { // symlink(target, path, flags, undefinec, ctx) @@ -1127,6 +1236,12 @@ static void Link(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // link(src, dest, req) + FS_ASYNC_TRACE_BEGIN2(UV_FS_LINK, + req_wrap_async, + "src", + TRACE_STR_COPY(*src), + "dest", + TRACE_STR_COPY(*dest)) AsyncDestCall(env, req_wrap_async, args, "link", *dest, dest.length(), UTF8, AfterNoArgs, uv_fs_link, *src, *dest); } else { // link(src, dest) @@ -1153,6 +1268,8 @@ static void ReadLink(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // readlink(path, encoding, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_READLINK, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "readlink", encoding, AfterStringPtr, uv_fs_readlink, *path); } else { @@ -1196,6 +1313,12 @@ static void Rename(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { + FS_ASYNC_TRACE_BEGIN2(UV_FS_RENAME, + req_wrap_async, + "old_path", + TRACE_STR_COPY(*old_path), + "new_path", + TRACE_STR_COPY(*new_path)) AsyncDestCall(env, req_wrap_async, args, "rename", *new_path, new_path.length(), UTF8, AfterNoArgs, uv_fs_rename, *old_path, *new_path); @@ -1223,6 +1346,7 @@ static void FTruncate(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { + FS_ASYNC_TRACE_BEGIN0(UV_FS_FTRUNCATE, req_wrap_async) AsyncCall(env, req_wrap_async, args, "ftruncate", UTF8, AfterNoArgs, uv_fs_ftruncate, fd, len); } else { @@ -1246,6 +1370,7 @@ static void Fdatasync(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 1); if (req_wrap_async != nullptr) { + FS_ASYNC_TRACE_BEGIN0(UV_FS_FDATASYNC, req_wrap_async) AsyncCall(env, req_wrap_async, args, "fdatasync", UTF8, AfterNoArgs, uv_fs_fdatasync, fd); } else { @@ -1268,6 +1393,7 @@ static void Fsync(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 1); if (req_wrap_async != nullptr) { + FS_ASYNC_TRACE_BEGIN0(UV_FS_FSYNC, req_wrap_async) AsyncCall(env, req_wrap_async, args, "fsync", UTF8, AfterNoArgs, uv_fs_fsync, fd); } else { @@ -1290,6 +1416,8 @@ static void Unlink(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 1); if (req_wrap_async != nullptr) { + FS_ASYNC_TRACE_BEGIN1( + UV_FS_UNLINK, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "unlink", UTF8, AfterNoArgs, uv_fs_unlink, *path); } else { @@ -1312,6 +1440,8 @@ static void RMDir(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 1); // rmdir(path, req) if (req_wrap_async != nullptr) { + FS_ASYNC_TRACE_BEGIN1( + UV_FS_RMDIR, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "rmdir", UTF8, AfterNoArgs, uv_fs_rmdir, *path); } else { // rmdir(path, undefined, ctx) @@ -1523,6 +1653,8 @@ static void MKDir(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // mkdir(path, mode, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_UNLINK, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "mkdir", UTF8, mkdirp ? AfterMkdirp : AfterNoArgs, mkdirp ? MKDirpAsync : uv_fs_mkdir, *path, mode); @@ -1569,6 +1701,8 @@ static void RealPath(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // realpath(path, encoding, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_REALPATH, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "realpath", encoding, AfterStringPtr, uv_fs_realpath, *path); } else { // realpath(path, encoding, undefined, ctx) @@ -1616,6 +1750,8 @@ static void ReadDir(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // readdir(path, encoding, withTypes, req) req_wrap_async->set_with_file_types(with_types); + FS_ASYNC_TRACE_BEGIN1( + UV_FS_SCANDIR, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, @@ -1707,6 +1843,8 @@ static void Open(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // open(path, flags, mode, req) req_wrap_async->set_is_plain_open(true); + FS_ASYNC_TRACE_BEGIN1( + UV_FS_OPEN, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "open", UTF8, AfterInteger, uv_fs_open, *path, flags, mode); } else { // open(path, flags, mode, undefined, ctx) @@ -1740,6 +1878,8 @@ static void OpenFileHandle(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // openFileHandle(path, flags, mode, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_OPEN, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "open", UTF8, AfterOpenFileHandle, uv_fs_open, *path, flags, mode); } else { // openFileHandle(path, flags, mode, undefined, ctx) @@ -1776,6 +1916,12 @@ static void CopyFile(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // copyFile(src, dest, flags, req) + FS_ASYNC_TRACE_BEGIN2(UV_FS_COPYFILE, + req_wrap_async, + "src", + TRACE_STR_COPY(*src), + "dest", + TRACE_STR_COPY(*dest)) AsyncDestCall(env, req_wrap_async, args, "copyfile", *dest, dest.length(), UTF8, AfterNoArgs, uv_fs_copyfile, *src, *dest, flags); @@ -1832,6 +1978,7 @@ static void WriteBuffer(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 5); if (req_wrap_async != nullptr) { // write(fd, buffer, off, len, pos, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_WRITE, req_wrap_async) AsyncCall(env, req_wrap_async, args, "write", UTF8, AfterInteger, uv_fs_write, fd, &uvbuf, 1, pos); } else { // write(fd, buffer, off, len, pos, undefined, ctx) @@ -1877,6 +2024,7 @@ static void WriteBuffers(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // writeBuffers(fd, chunks, pos, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_WRITE, req_wrap_async) AsyncCall(env, req_wrap_async, args, "write", UTF8, AfterInteger, uv_fs_write, fd, *iovs, iovs.length(), pos); } else { // writeBuffers(fd, chunks, pos, undefined, ctx) @@ -1950,6 +2098,7 @@ static void WriteString(const FunctionCallbackInfo& args) { len = StringBytes::Write(isolate, *stack_buffer, len, args[1], enc); stack_buffer.SetLengthAndZeroTerminate(len); uv_buf_t uvbuf = uv_buf_init(*stack_buffer, len); + FS_ASYNC_TRACE_BEGIN0(UV_FS_WRITE, req_wrap_async) int err = req_wrap_async->Dispatch(uv_fs_write, fd, &uvbuf, @@ -2035,6 +2184,7 @@ static void Read(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 5); if (req_wrap_async != nullptr) { // read(fd, buffer, offset, len, pos, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_READ, req_wrap_async) AsyncCall(env, req_wrap_async, args, "read", UTF8, AfterInteger, uv_fs_read, fd, &uvbuf, 1, pos); } else { // read(fd, buffer, offset, len, pos, undefined, ctx) @@ -2081,6 +2231,7 @@ static void ReadBuffers(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // readBuffers(fd, buffers, pos, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_READ, req_wrap_async) AsyncCall(env, req_wrap_async, args, "read", UTF8, AfterInteger, uv_fs_read, fd, *iovs, iovs.length(), pos); } else { // readBuffers(fd, buffers, undefined, ctx) @@ -2112,6 +2263,8 @@ static void Chmod(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // chmod(path, mode, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_CHMOD, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "chmod", UTF8, AfterNoArgs, uv_fs_chmod, *path, mode); } else { // chmod(path, mode, undefined, ctx) @@ -2142,6 +2295,7 @@ static void FChmod(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // fchmod(fd, mode, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_FCHMOD, req_wrap_async) AsyncCall(env, req_wrap_async, args, "fchmod", UTF8, AfterNoArgs, uv_fs_fchmod, fd, mode); } else { // fchmod(fd, mode, undefined, ctx) @@ -2175,6 +2329,8 @@ static void Chown(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // chown(path, uid, gid, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_CHOWN, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "chown", UTF8, AfterNoArgs, uv_fs_chown, *path, uid, gid); } else { // chown(path, uid, gid, undefined, ctx) @@ -2208,6 +2364,7 @@ static void FChown(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // fchown(fd, uid, gid, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_FCHOWN, req_wrap_async) AsyncCall(env, req_wrap_async, args, "fchown", UTF8, AfterNoArgs, uv_fs_fchown, fd, uid, gid); } else { // fchown(fd, uid, gid, undefined, ctx) @@ -2238,6 +2395,8 @@ static void LChown(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // lchown(path, uid, gid, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_LCHOWN, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "lchown", UTF8, AfterNoArgs, uv_fs_lchown, *path, uid, gid); } else { // lchown(path, uid, gid, undefined, ctx) @@ -2268,6 +2427,8 @@ static void UTimes(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // utimes(path, atime, mtime, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_UTIME, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "utime", UTF8, AfterNoArgs, uv_fs_utime, *path, atime, mtime); } else { // utimes(path, atime, mtime, undefined, ctx) @@ -2297,6 +2458,7 @@ static void FUTimes(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // futimes(fd, atime, mtime, req) + FS_ASYNC_TRACE_BEGIN0(UV_FS_FUTIME, req_wrap_async) AsyncCall(env, req_wrap_async, args, "futime", UTF8, AfterNoArgs, uv_fs_futime, fd, atime, mtime); } else { // futimes(fd, atime, mtime, undefined, ctx) @@ -2326,6 +2488,8 @@ static void LUTimes(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 3); if (req_wrap_async != nullptr) { // lutimes(path, atime, mtime, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_LUTIME, req_wrap_async, "path", TRACE_STR_COPY(*path)) AsyncCall(env, req_wrap_async, args, "lutime", UTF8, AfterNoArgs, uv_fs_lutime, *path, atime, mtime); } else { // lutimes(path, atime, mtime, undefined, ctx) @@ -2352,6 +2516,8 @@ static void Mkdtemp(const FunctionCallbackInfo& args) { FSReqBase* req_wrap_async = GetReqWrap(args, 2); if (req_wrap_async != nullptr) { // mkdtemp(tmpl, encoding, req) + FS_ASYNC_TRACE_BEGIN1( + UV_FS_MKDTEMP, req_wrap_async, "path", TRACE_STR_COPY(*tmpl)) AsyncCall(env, req_wrap_async, args, "mkdtemp", encoding, AfterStringPath, uv_fs_mkdtemp, *tmpl); } else { // mkdtemp(tmpl, encoding, undefined, ctx) diff --git a/test/parallel/test-trace-events-fs-async.js b/test/parallel/test-trace-events-fs-async.js new file mode 100644 index 00000000000000..693214832a9167 --- /dev/null +++ b/test/parallel/test-trace-events-fs-async.js @@ -0,0 +1,341 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const cp = require('child_process'); +const fs = require('fs'); +const path = require('path'); +const util = require('util'); + +const tests = Object.create(null); + +let gid = 1; +let uid = 1; + +if (!common.isWindows) { + gid = process.getgid(); + uid = process.getuid(); +} + +function wrapper(func, args) { + return `(${func.toString()})(${JSON.stringify(args)})`; +} + +function access() { + const fs = require('fs'); + fs.writeFileSync('fs0.txt', '123', 'utf8'); + fs.access('fs0.txt', () => { + fs.unlinkSync('fs0.txt'); + }); +} + +function chmod() { + const fs = require('fs'); + fs.writeFileSync('fs1.txt', '123', 'utf8'); + fs.chmod('fs1.txt', 100, () => { + fs.unlinkSync('fs1.txt'); + }); +} + +function chown({ uid, gid }) { + const fs = require('fs'); + fs.writeFileSync('fs2.txt', '123', 'utf8'); + fs.chown('fs2.txt', uid, gid, () => { + fs.unlinkSync('fs2.txt'); + }); +} + +function close() { + const fs = require('fs'); + fs.writeFile('fs3.txt', '123', 'utf8', () => { + fs.unlinkSync('fs3.txt'); + }); +} + +function copyfile() { + const fs = require('fs'); + fs.writeFileSync('fs4.txt', '123', 'utf8'); + fs.copyFile('fs4.txt', 'a.txt', () => { + fs.unlinkSync('fs4.txt'); + fs.unlinkSync('a.txt'); + }); +} + +function fchmod() { + const fs = require('fs'); + fs.writeFileSync('fs5.txt', '123', 'utf8'); + const fd = fs.openSync('fs5.txt', 'r+'); + fs.fchmod(fd, 100, () => { + fs.unlinkSync('fs5.txt'); + }); +} + +function fchown({ uid, gid }) { + const fs = require('fs'); + fs.writeFileSync('fs6.txt', '123', 'utf8'); + const fd = fs.openSync('fs6.txt', 'r+'); + fs.fchown(fd, uid, gid, () => { + fs.unlinkSync('fs6.txt'); + }); +} + +function fdatasync() { + const fs = require('fs'); + fs.writeFileSync('fs7.txt', '123', 'utf8'); + const fd = fs.openSync('fs7.txt', 'r+'); + fs.fdatasync(fd, () => { + fs.unlinkSync('fs7.txt'); + }); +} + +function fstat() { + const fs = require('fs'); + fs.writeFileSync('fs8.txt', '123', 'utf8'); + fs.readFile('fs8.txt', () => { + fs.unlinkSync('fs8.txt'); + }); +} + +function fsync() { + const fs = require('fs'); + fs.writeFileSync('fs9.txt', '123', 'utf8'); + const fd = fs.openSync('fs9.txt', 'r+'); + fs.fsync(fd, () => { + fs.unlinkSync('fs9.txt'); + }); +} + +function ftruncate() { + const fs = require('fs'); + fs.writeFileSync('fs10.txt', '123', 'utf8'); + const fd = fs.openSync('fs10.txt', 'r+'); + fs.ftruncate(fd, 1, () => { + fs.unlinkSync('fs10.txt'); + }); +} + +function futime() { + const fs = require('fs'); + fs.writeFileSync('fs11.txt', '123', 'utf8'); + const fd = fs.openSync('fs11.txt', 'r+'); + fs.futimes(fd, 1, 1, () => { + fs.unlinkSync('fs11.txt'); + }); +} + +function lutime() { + const fs = require('fs'); + fs.writeFileSync('fs111.txt', '123', 'utf8'); + fs.lutimes('fs111.txt', 1, 1, () => { + fs.unlinkSync('fs111.txt'); + }); +} + +function lchown({ uid, gid }) { + const fs = require('fs'); + fs.writeFileSync('fs12.txt', '123', 'utf8'); + fs.lchown('fs12.txt', uid, gid, () => { + fs.unlinkSync('fs12.txt'); + }); +} + +function link() { + const fs = require('fs'); + fs.writeFileSync('fs13.txt', '123', 'utf8'); + fs.link('fs13.txt', 'fs14.txt', () => { + fs.unlinkSync('fs13.txt'); + fs.unlinkSync('fs14.txt'); + }); +} + +function lstat() { + const fs = require('fs'); + fs.writeFileSync('fs15.txt', '123', 'utf8'); + fs.lstat('fs15.txt', () => { + fs.unlinkSync('fs15.txt'); + }); +} + +function mkdir() { + const fs = require('fs'); + fs.mkdir('fstemp0', () => { + fs.rmdir('fstemp0', () => {}); + }); +} + +function mktmp() { + fs.mkdtemp('fstemp1', (err, fp) => { + fs.rmdir(fp, () => {}); + }); +} + +function open() { + const fs = require('fs'); + fs.writeFile('fs16.txt', '123', 'utf8', () => { + fs.unlinkSync('fs16.txt'); + }); +} + +function read() { + const fs = require('fs'); + fs.writeFileSync('fs17.txt', '123', 'utf8'); + fs.readFile('fs17.txt', () => { + fs.unlinkSync('fs17.txt'); + }); +} + +function readdir() { + const fs = require('fs'); + fs.readdir('./', () => {}); +} + +function opendir() { + const fs = require('fs'); + fs.opendir('./', () => {}); +} + +function realpath() { + const fs = require('fs'); + fs.writeFileSync('fs18.txt', '123', 'utf8'); + fs.linkSync('fs18.txt', 'fs19.txt'); + fs.realpath.native('fs19.txt', () => { + fs.unlinkSync('fs18.txt'); + fs.unlinkSync('fs19.txt'); + }); +} + +function rename() { + const fs = require('fs'); + fs.writeFileSync('fs20.txt', '123', 'utf8'); + fs.rename('fs20.txt', 'fs21.txt', () => { + fs.unlinkSync('fs21.txt'); + }); +} + +function rmdir() { + const fs = require('fs'); + fs.mkdirSync('fstemp2'); + fs.rmdir('fstemp2', () => {}); +} + +function stat() { + const fs = require('fs'); + fs.writeFileSync('fs22.txt', '123', 'utf8'); + fs.stat('fs22.txt', () => { + fs.unlinkSync('fs22.txt'); + }); +} + +function unlink() { + const fs = require('fs'); + fs.writeFileSync('fs23.txt', '123', 'utf8'); + fs.linkSync('fs23.txt', 'fs24.txt'); + fs.unlink('fs23.txt', () => {}); + fs.unlink('fs24.txt', () => {}); +} + +function utime() { + const fs = require('fs'); + fs.writeFileSync('fs25.txt', '123', 'utf8'); + fs.utimes('fs25.txt', 1, 1, () => { + fs.unlinkSync('fs25.txt'); + }); +} + +function write() { + const fs = require('fs'); + fs.writeFile('fs26.txt', '123', 'utf8', () => { + fs.unlinkSync('fs26.txt'); + }); +} + +function symlink() { + const fs = require('fs'); + fs.writeFileSync('fs27.txt', '123', 'utf8'); + fs.symlink('fs27.txt', 'fs28.txt', () => { + fs.unlinkSync('fs27.txt'); + fs.unlinkSync('fs28.txt'); + }); +} + +function readlink() { + const fs = require('fs'); + fs.writeFileSync('fs29.txt', '123', 'utf8'); + fs.symlinkSync('fs29.txt', 'fs30.txt'); + fs.readlink('fs30.txt', () => { + fs.unlinkSync('fs29.txt'); + fs.unlinkSync('fs30.txt'); + }); +} +// The key defined in get_fs_name_by_type function in node_file.cc and node_dir.cc +tests.access = wrapper(access); +tests.chmod = wrapper(chmod); +tests.chown = wrapper(chown, { uid, gid }); +tests.close = wrapper(close); +tests.copyfile = wrapper(copyfile); +tests.fchmod = wrapper(fchmod); +tests.fchown = wrapper(fchown, { uid, gid }); +tests.fdatasync = wrapper(fdatasync); +tests.fstat = wrapper(fstat); +tests.fsync = wrapper(fsync); +tests.ftruncate = wrapper(ftruncate); +tests.futime = wrapper(futime); +tests.lutime = wrapper(lutime); +tests.lchown = wrapper(lchown, { uid, gid }); +tests.link = wrapper(link); +tests.lstat = wrapper(lstat); +tests.mkdir = wrapper(mkdir); +tests.mkdtemp = wrapper(mktmp); +tests.open = wrapper(open); +tests.read = wrapper(read); +tests.scandir = wrapper(readdir); +tests.opendir = wrapper(opendir); +tests.realpath = wrapper(realpath); +tests.rename = wrapper(rename); +tests.rmdir = wrapper(rmdir); +tests.stat = wrapper(stat); +tests.unlink = wrapper(unlink); +tests.utime = wrapper(utime); +tests.write = wrapper(write); + +// On windows, we need permissions to test symlink and readlink. +// We'll only try to run these tests if we have enough privileges. +if (common.canCreateSymLink()) { + tests.symlink = wrapper(symlink); + tests.readlink = wrapper(readlink); +} +const tmpdir = require('../common/tmpdir'); +tmpdir.refresh(); +const traceFile = path.join(tmpdir.path, 'node_trace.1.log'); + +for (const tr in tests) { + const proc = cp.spawnSync(process.execPath, + [ '--trace-events-enabled', + '--trace-event-categories', 'node.fs_dir.async,node.fs.async', + '-e', tests[tr] ], + { cwd: tmpdir.path, encoding: 'utf8' }); + + // Make sure the operation is successful. + // Don't use assert with a custom message here. Otherwise the + // inspection in the message is done eagerly and wastes a lot of CPU + // time. + if (proc.status !== 0) { + throw new Error(`${tr}:\n${util.inspect(proc)}`); + } + + // Confirm that trace log file is created. + assert(fs.existsSync(traceFile)); + const data = fs.readFileSync(traceFile); + const { traceEvents } = JSON.parse(data.toString()); + // Confirm that the data we want is produced + const traces = traceEvents.filter((item) => { + return [ + 'node,node.fs,node.fs.async', + 'node,node.fs_dir,node.fs_dir.async', + ].includes(item.cat); + }); + // Confirm that the data we want is produced + assert(traces.length > 0); + assert(traces.some((trace) => { + return trace.name === tr; + })); +}