Skip to content

Commit

Permalink
src: add sync trace to fs
Browse files Browse the repository at this point in the history 
Add sync trace to fs operations which
is enabled by the node.fs.sync trace event
category. Also add a general test js file
to verify all operations.

PR-URL: #19649
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>
Reviewed-By: Michael Dawson <michael_dawson@ca.ibm.com>
  • Loading branch information
@chinhuang007 @jasnell
chinhuang007 authored and jasnell committed Apr 16, 2018
1 parent 44856f7 commit 2d40895
Show file tree
Hide file tree
Showing 3 changed files with 244 additions and 1 deletion.
77 changes: 76 additions & 1 deletion src/node_file.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@
#include "node_internals.h"
#include "node_stat_watcher.h"
#include "node_file.h"
#include "tracing/trace_event.h"

#include "req_wrap-inl.h"
#include "stream_base-inl.h"
Expand Down Expand Up @@ -75,6 +76,18 @@ using v8::Value;
#endif

#define GET_OFFSET(a) ((a)->IsNumber() ? (a).As<Integer>()->Value() : -1)
#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__);

// The FileHandle object wraps a file descriptor and will close it on garbage
// collection if necessary. If that happens, a process warning will be
Expand Down Expand Up @@ -316,7 +329,7 @@ int FileHandle::ReadStart() {

// ReadStart() checks whether current_read_ is set to determine whether
// a read is in progress. Moving it into a local variable makes sure that
// the ReadStart() call below doesn’t think we’re still actively reading.
// the ReadStart() call below doesn't think we're still actively reading.
std::unique_ptr<FileHandleReadWrap> read_wrap =
std::move(handle->current_read_);

Expand Down Expand Up @@ -683,7 +696,9 @@ void Access(const FunctionCallbackInfo<Value>& args) {
} else { // access(path, mode, undefined, ctx)
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(access);
SyncCall(env, args[3], &req_wrap_sync, "access", uv_fs_access, *path, mode);
FS_SYNC_TRACE_END(access);
}
}

Expand All @@ -704,7 +719,9 @@ void Close(const FunctionCallbackInfo<Value>& args) {
} else { // close(fd, undefined, ctx)
CHECK_EQ(argc, 3);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(close);
SyncCall(env, args[2], &req_wrap_sync, "close", uv_fs_close, fd);
FS_SYNC_TRACE_END(close);
}
}

Expand Down Expand Up @@ -812,7 +829,9 @@ static void Stat(const FunctionCallbackInfo<Value>& args) {
} else { // stat(path, undefined, ctx)
CHECK_EQ(argc, 3);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(stat);
int err = SyncCall(env, args[2], &req_wrap_sync, "stat", uv_fs_stat, *path);
FS_SYNC_TRACE_END(stat);
if (err == 0) {
node::FillGlobalStatsArray(env,
static_cast<const uv_stat_t*>(req_wrap_sync.req.ptr));
Expand All @@ -836,8 +855,10 @@ static void LStat(const FunctionCallbackInfo<Value>& args) {
} else { // lstat(path, undefined, ctx)
CHECK_EQ(argc, 3);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(lstat);
int err = SyncCall(env, args[2], &req_wrap_sync, "lstat", uv_fs_lstat,
*path);
FS_SYNC_TRACE_END(lstat);
if (err == 0) {
node::FillGlobalStatsArray(env,
static_cast<const uv_stat_t*>(req_wrap_sync.req.ptr));
Expand All @@ -861,7 +882,9 @@ static void FStat(const FunctionCallbackInfo<Value>& args) {
} else { // fstat(fd, undefined, ctx)
CHECK_EQ(argc, 3);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(fstat);
int err = SyncCall(env, args[2], &req_wrap_sync, "fstat", uv_fs_fstat, fd);
FS_SYNC_TRACE_END(fstat);
if (err == 0) {
node::FillGlobalStatsArray(env,
static_cast<const uv_stat_t*>(req_wrap_sync.req.ptr));
Expand Down Expand Up @@ -890,8 +913,10 @@ static void Symlink(const FunctionCallbackInfo<Value>& args) {
} else { // symlink(target, path, flags, undefinec, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(symlink);
SyncCall(env, args[4], &req_wrap_sync, "symlink",
uv_fs_symlink, *target, *path, flags);
FS_SYNC_TRACE_END(symlink);
}
}

Expand All @@ -914,8 +939,10 @@ static void Link(const FunctionCallbackInfo<Value>& args) {
} else { // link(src, dest)
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(link);
SyncCall(env, args[3], &req_wrap_sync, "link",
uv_fs_link, *src, *dest);
FS_SYNC_TRACE_END(link);
}
}

Expand All @@ -937,8 +964,10 @@ static void ReadLink(const FunctionCallbackInfo<Value>& args) {
} else {
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(readlink);
int err = SyncCall(env, args[3], &req_wrap_sync, "readlink",
uv_fs_readlink, *path);
FS_SYNC_TRACE_END(readlink);
if (err < 0) {
return; // syscall failed, no need to continue, error info is in ctx
}
Expand Down Expand Up @@ -978,8 +1007,10 @@ static void Rename(const FunctionCallbackInfo<Value>& args) {
} else {
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(rename);
SyncCall(env, args[3], &req_wrap_sync, "rename", uv_fs_rename,
*old_path, *new_path);
FS_SYNC_TRACE_END(rename);
}
}

Expand All @@ -1002,8 +1033,10 @@ static void FTruncate(const FunctionCallbackInfo<Value>& args) {
} else {
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(ftruncate);
SyncCall(env, args[3], &req_wrap_sync, "ftruncate", uv_fs_ftruncate, fd,
len);
FS_SYNC_TRACE_END(ftruncate);
}
}

Expand All @@ -1023,7 +1056,9 @@ static void Fdatasync(const FunctionCallbackInfo<Value>& args) {
} else {
CHECK_EQ(argc, 3);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(fdatasync);
SyncCall(env, args[2], &req_wrap_sync, "fdatasync", uv_fs_fdatasync, fd);
FS_SYNC_TRACE_END(fdatasync);
}
}

Expand All @@ -1043,7 +1078,9 @@ static void Fsync(const FunctionCallbackInfo<Value>& args) {
} else {
CHECK_EQ(argc, 3);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(fsync);
SyncCall(env, args[2], &req_wrap_sync, "fsync", uv_fs_fsync, fd);
FS_SYNC_TRACE_END(fsync);
}
}

Expand All @@ -1063,7 +1100,9 @@ static void Unlink(const FunctionCallbackInfo<Value>& args) {
} else {
CHECK_EQ(argc, 3);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(unlink);
SyncCall(env, args[2], &req_wrap_sync, "unlink", uv_fs_unlink, *path);
FS_SYNC_TRACE_END(unlink);
}
}

Expand All @@ -1083,8 +1122,10 @@ static void RMDir(const FunctionCallbackInfo<Value>& args) {
} else { // rmdir(path, undefined, ctx)
CHECK_EQ(argc, 3);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(rmdir);
SyncCall(env, args[2], &req_wrap_sync, "rmdir",
uv_fs_rmdir, *path);
FS_SYNC_TRACE_END(rmdir);
}
}

Expand All @@ -1107,8 +1148,10 @@ static void MKDir(const FunctionCallbackInfo<Value>& args) {
} else { // mkdir(path, mode, undefined, ctx)
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(mkdir);
SyncCall(env, args[3], &req_wrap_sync, "mkdir",
uv_fs_mkdir, *path, mode);
FS_SYNC_TRACE_END(mkdir);
}
}

Expand All @@ -1130,8 +1173,10 @@ static void RealPath(const FunctionCallbackInfo<Value>& args) {
} else { // realpath(path, encoding, undefined, ctx)
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(realpath);
int err = SyncCall(env, args[3], &req_wrap_sync, "realpath",
uv_fs_realpath, *path);
FS_SYNC_TRACE_END(realpath);
if (err < 0) {
return; // syscall failed, no need to continue, error info is in ctx
}
Expand Down Expand Up @@ -1171,8 +1216,10 @@ static void ReadDir(const FunctionCallbackInfo<Value>& args) {
} else { // readdir(path, encoding, undefined, ctx)
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(readdir);
int err = SyncCall(env, args[3], &req_wrap_sync, "scandir",
uv_fs_scandir, *path, 0 /*flags*/);
FS_SYNC_TRACE_END(readdir);
if (err < 0) {
return; // syscall failed, no need to continue, error info is in ctx
}
Expand Down Expand Up @@ -1255,8 +1302,10 @@ static void Open(const FunctionCallbackInfo<Value>& args) {
} else { // open(path, flags, mode, undefined, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(open);
int result = SyncCall(env, args[4], &req_wrap_sync, "open",
uv_fs_open, *path, flags, mode);
FS_SYNC_TRACE_END(open);
args.GetReturnValue().Set(result);
}
}
Expand All @@ -1283,8 +1332,10 @@ static void OpenFileHandle(const FunctionCallbackInfo<Value>& args) {
} else { // openFileHandle(path, flags, mode, undefined, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(open);
int result = SyncCall(env, args[4], &req_wrap_sync, "open",
uv_fs_open, *path, flags, mode);
FS_SYNC_TRACE_END(open);
if (result < 0) {
return; // syscall failed, no need to continue, error info is in ctx
}
Expand Down Expand Up @@ -1317,8 +1368,10 @@ static void CopyFile(const FunctionCallbackInfo<Value>& args) {
} else { // copyFile(src, dest, flags, undefined, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(copyfile);
SyncCall(env, args[4], &req_wrap_sync, "copyfile",
uv_fs_copyfile, *src, *dest, flags);
FS_SYNC_TRACE_END(copyfile);
}
}

Expand Down Expand Up @@ -1368,8 +1421,10 @@ static void WriteBuffer(const FunctionCallbackInfo<Value>& args) {
} else { // write(fd, buffer, off, len, pos, undefined, ctx)
CHECK_EQ(argc, 7);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(write);
int bytesWritten = SyncCall(env, args[6], &req_wrap_sync, "write",
uv_fs_write, fd, &uvbuf, 1, pos);
FS_SYNC_TRACE_END(write, "bytesWritten", bytesWritten);
args.GetReturnValue().Set(bytesWritten);
}
}
Expand Down Expand Up @@ -1411,8 +1466,10 @@ static void WriteBuffers(const FunctionCallbackInfo<Value>& args) {
} else { // writeBuffers(fd, chunks, pos, undefined, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(write);
int bytesWritten = SyncCall(env, args[4], &req_wrap_sync, "write",
uv_fs_write, fd, *iovs, iovs.length(), pos);
FS_SYNC_TRACE_END(write, "bytesWritten", bytesWritten);
args.GetReturnValue().Set(bytesWritten);
}
}
Expand Down Expand Up @@ -1503,8 +1560,10 @@ static void WriteString(const FunctionCallbackInfo<Value>& args) {
buf = *stack_buffer;
}
uv_buf_t uvbuf = uv_buf_init(buf, len);
FS_SYNC_TRACE_BEGIN(write);
int bytesWritten = SyncCall(env, args[5], &req_wrap_sync, "write",
uv_fs_write, fd, &uvbuf, 1, pos);
FS_SYNC_TRACE_END(write, "bytesWritten", bytesWritten);
args.GetReturnValue().Set(bytesWritten);
}
}
Expand Down Expand Up @@ -1556,8 +1615,10 @@ static void Read(const FunctionCallbackInfo<Value>& args) {
} else { // read(fd, buffer, offset, len, pos, undefined, ctx)
CHECK_EQ(argc, 7);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(read);
const int bytesRead = SyncCall(env, args[6], &req_wrap_sync, "read",
uv_fs_read, fd, &uvbuf, 1, pos);
FS_SYNC_TRACE_END(read, "bytesRead", bytesRead);
args.GetReturnValue().Set(bytesRead);
}
}
Expand Down Expand Up @@ -1585,8 +1646,10 @@ static void Chmod(const FunctionCallbackInfo<Value>& args) {
} else { // chmod(path, mode, undefined, ctx)
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(chmod);
SyncCall(env, args[3], &req_wrap_sync, "chmod",
uv_fs_chmod, *path, mode);
FS_SYNC_TRACE_END(chmod);
}
}

Expand All @@ -1613,8 +1676,10 @@ static void FChmod(const FunctionCallbackInfo<Value>& args) {
} else { // fchmod(fd, mode, undefined, ctx)
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(fchmod);
SyncCall(env, args[3], &req_wrap_sync, "fchmod",
uv_fs_fchmod, fd, mode);
FS_SYNC_TRACE_END(fchmod);
}
}

Expand Down Expand Up @@ -1644,8 +1709,10 @@ static void Chown(const FunctionCallbackInfo<Value>& args) {
} else { // chown(path, uid, gid, undefined, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(chown);
SyncCall(env, args[4], &req_wrap_sync, "chown",
uv_fs_chown, *path, uid, gid);
FS_SYNC_TRACE_END(chown);
}
}

Expand Down Expand Up @@ -1675,8 +1742,10 @@ static void FChown(const FunctionCallbackInfo<Value>& args) {
} else { // fchown(fd, uid, gid, undefined, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(fchown);
SyncCall(env, args[4], &req_wrap_sync, "fchown",
uv_fs_fchown, fd, uid, gid);
FS_SYNC_TRACE_END(fchown);
}
}

Expand All @@ -1703,8 +1772,10 @@ static void UTimes(const FunctionCallbackInfo<Value>& args) {
} else { // utimes(path, atime, mtime, undefined, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(utimes);
SyncCall(env, args[4], &req_wrap_sync, "utime",
uv_fs_utime, *path, atime, mtime);
FS_SYNC_TRACE_END(utimes);
}
}

Expand All @@ -1730,8 +1801,10 @@ static void FUTimes(const FunctionCallbackInfo<Value>& args) {
} else { // futimes(fd, atime, mtime, undefined, ctx)
CHECK_EQ(argc, 5);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(futimes);
SyncCall(env, args[4], &req_wrap_sync, "futime",
uv_fs_futime, fd, atime, mtime);
FS_SYNC_TRACE_END(futimes);
}
}

Expand All @@ -1753,8 +1826,10 @@ static void Mkdtemp(const FunctionCallbackInfo<Value>& args) {
} else { // mkdtemp(tmpl, encoding, undefined, ctx)
CHECK_EQ(argc, 4);
FSReqWrapSync req_wrap_sync;
FS_SYNC_TRACE_BEGIN(mkdtemp);
SyncCall(env, args[3], &req_wrap_sync, "mkdtemp",
uv_fs_mkdtemp, *tmpl);
FS_SYNC_TRACE_END(mkdtemp);
const char* path = static_cast<const char*>(req_wrap_sync.req.path);

Local<Value> error;
Expand Down
6 changes: 6 additions & 0 deletions src/tracing/trace_event_common.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -271,6 +271,9 @@
// does nothing.
// - category and name strings must have application lifetime (statics or
// literals). They may not include " chars.
#define TRACE_EVENT_BEGIN(category_group, name, ...) \
INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category_group, name, \
TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__)
#define TRACE_EVENT_BEGIN0(category_group, name) \
INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category_group, name, \
TRACE_EVENT_FLAG_NONE)
Expand Down Expand Up @@ -327,6 +330,9 @@
// is not enabled, then this does nothing.
// - category and name strings must have application lifetime (statics or
// literals). They may not include " chars.
#define TRACE_EVENT_END(category_group, name, ...) \
INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category_group, name, \
TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__)
#define TRACE_EVENT_END0(category_group, name) \
INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category_group, name, \
TRACE_EVENT_FLAG_NONE)
Expand Down
Loading

0 comments on commit 2d40895

Please sign in to comment.