Skip to content

Commit 2d40895

Browse files
chinhuang007jasnell
chinhuang007
authored and
jasnell
committed
src: add sync trace to fs
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>
1 parent 44856f7 commit 2d40895

File tree

3 files changed

+244
-1
lines changed

3 files changed

+244
-1
lines changed

‎src/node_file.cc

Lines changed: 76 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@
2424
#include "node_internals.h"
2525
#include "node_stat_watcher.h"
2626
#include "node_file.h"
27+
#include "tracing/trace_event.h"
2728

2829
#include "req_wrap-inl.h"
2930
#include "stream_base-inl.h"
@@ -75,6 +76,18 @@ using v8::Value;
7576
#endif
7677

7778
#define GET_OFFSET(a) ((a)->IsNumber() ? (a).As<Integer>()->Value() : -1)
79+
#define TRACE_NAME(name) "fs.sync." #name
80+
#define GET_TRACE_ENABLED \
81+
(*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED \
82+
(TRACING_CATEGORY_NODE2(fs, sync)) != 0)
83+
#define FS_SYNC_TRACE_BEGIN(syscall, ...) \
84+
if (GET_TRACE_ENABLED) \
85+
TRACE_EVENT_BEGIN(TRACING_CATEGORY_NODE2(fs, sync), TRACE_NAME(syscall), \
86+
##__VA_ARGS__);
87+
#define FS_SYNC_TRACE_END(syscall, ...) \
88+
if (GET_TRACE_ENABLED) \
89+
TRACE_EVENT_END(TRACING_CATEGORY_NODE2(fs, sync), TRACE_NAME(syscall), \
90+
##__VA_ARGS__);
7891

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

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

@@ -683,7 +696,9 @@ void Access(const FunctionCallbackInfo<Value>& args) {
683696
} else { // access(path, mode, undefined, ctx)
684697
CHECK_EQ(argc, 4);
685698
FSReqWrapSync req_wrap_sync;
699+
FS_SYNC_TRACE_BEGIN(access);
686700
SyncCall(env, args[3], &req_wrap_sync, "access", uv_fs_access, *path, mode);
701+
FS_SYNC_TRACE_END(access);
687702
}
688703
}
689704

@@ -704,7 +719,9 @@ void Close(const FunctionCallbackInfo<Value>& args) {
704719
} else { // close(fd, undefined, ctx)
705720
CHECK_EQ(argc, 3);
706721
FSReqWrapSync req_wrap_sync;
722+
FS_SYNC_TRACE_BEGIN(close);
707723
SyncCall(env, args[2], &req_wrap_sync, "close", uv_fs_close, fd);
724+
FS_SYNC_TRACE_END(close);
708725
}
709726
}
710727

@@ -812,7 +829,9 @@ static void Stat(const FunctionCallbackInfo<Value>& args) {
812829
} else { // stat(path, undefined, ctx)
813830
CHECK_EQ(argc, 3);
814831
FSReqWrapSync req_wrap_sync;
832+
FS_SYNC_TRACE_BEGIN(stat);
815833
int err = SyncCall(env, args[2], &req_wrap_sync, "stat", uv_fs_stat, *path);
834+
FS_SYNC_TRACE_END(stat);
816835
if (err == 0) {
817836
node::FillGlobalStatsArray(env,
818837
static_cast<const uv_stat_t*>(req_wrap_sync.req.ptr));
@@ -836,8 +855,10 @@ static void LStat(const FunctionCallbackInfo<Value>& args) {
836855
} else { // lstat(path, undefined, ctx)
837856
CHECK_EQ(argc, 3);
838857
FSReqWrapSync req_wrap_sync;
858+
FS_SYNC_TRACE_BEGIN(lstat);
839859
int err = SyncCall(env, args[2], &req_wrap_sync, "lstat", uv_fs_lstat,
840860
*path);
861+
FS_SYNC_TRACE_END(lstat);
841862
if (err == 0) {
842863
node::FillGlobalStatsArray(env,
843864
static_cast<const uv_stat_t*>(req_wrap_sync.req.ptr));
@@ -861,7 +882,9 @@ static void FStat(const FunctionCallbackInfo<Value>& args) {
861882
} else { // fstat(fd, undefined, ctx)
862883
CHECK_EQ(argc, 3);
863884
FSReqWrapSync req_wrap_sync;
885+
FS_SYNC_TRACE_BEGIN(fstat);
864886
int err = SyncCall(env, args[2], &req_wrap_sync, "fstat", uv_fs_fstat, fd);
887+
FS_SYNC_TRACE_END(fstat);
865888
if (err == 0) {
866889
node::FillGlobalStatsArray(env,
867890
static_cast<const uv_stat_t*>(req_wrap_sync.req.ptr));
@@ -890,8 +913,10 @@ static void Symlink(const FunctionCallbackInfo<Value>& args) {
890913
} else { // symlink(target, path, flags, undefinec, ctx)
891914
CHECK_EQ(argc, 5);
892915
FSReqWrapSync req_wrap_sync;
916+
FS_SYNC_TRACE_BEGIN(symlink);
893917
SyncCall(env, args[4], &req_wrap_sync, "symlink",
894918
uv_fs_symlink, *target, *path, flags);
919+
FS_SYNC_TRACE_END(symlink);
895920
}
896921
}
897922

@@ -914,8 +939,10 @@ static void Link(const FunctionCallbackInfo<Value>& args) {
914939
} else { // link(src, dest)
915940
CHECK_EQ(argc, 4);
916941
FSReqWrapSync req_wrap_sync;
942+
FS_SYNC_TRACE_BEGIN(link);
917943
SyncCall(env, args[3], &req_wrap_sync, "link",
918944
uv_fs_link, *src, *dest);
945+
FS_SYNC_TRACE_END(link);
919946
}
920947
}
921948

@@ -937,8 +964,10 @@ static void ReadLink(const FunctionCallbackInfo<Value>& args) {
937964
} else {
938965
CHECK_EQ(argc, 4);
939966
FSReqWrapSync req_wrap_sync;
967+
FS_SYNC_TRACE_BEGIN(readlink);
940968
int err = SyncCall(env, args[3], &req_wrap_sync, "readlink",
941969
uv_fs_readlink, *path);
970+
FS_SYNC_TRACE_END(readlink);
942971
if (err < 0) {
943972
return; // syscall failed, no need to continue, error info is in ctx
944973
}
@@ -978,8 +1007,10 @@ static void Rename(const FunctionCallbackInfo<Value>& args) {
9781007
} else {
9791008
CHECK_EQ(argc, 4);
9801009
FSReqWrapSync req_wrap_sync;
1010+
FS_SYNC_TRACE_BEGIN(rename);
9811011
SyncCall(env, args[3], &req_wrap_sync, "rename", uv_fs_rename,
9821012
*old_path, *new_path);
1013+
FS_SYNC_TRACE_END(rename);
9831014
}
9841015
}
9851016

@@ -1002,8 +1033,10 @@ static void FTruncate(const FunctionCallbackInfo<Value>& args) {
10021033
} else {
10031034
CHECK_EQ(argc, 4);
10041035
FSReqWrapSync req_wrap_sync;
1036+
FS_SYNC_TRACE_BEGIN(ftruncate);
10051037
SyncCall(env, args[3], &req_wrap_sync, "ftruncate", uv_fs_ftruncate, fd,
10061038
len);
1039+
FS_SYNC_TRACE_END(ftruncate);
10071040
}
10081041
}
10091042

@@ -1023,7 +1056,9 @@ static void Fdatasync(const FunctionCallbackInfo<Value>& args) {
10231056
} else {
10241057
CHECK_EQ(argc, 3);
10251058
FSReqWrapSync req_wrap_sync;
1059+
FS_SYNC_TRACE_BEGIN(fdatasync);
10261060
SyncCall(env, args[2], &req_wrap_sync, "fdatasync", uv_fs_fdatasync, fd);
1061+
FS_SYNC_TRACE_END(fdatasync);
10271062
}
10281063
}
10291064

@@ -1043,7 +1078,9 @@ static void Fsync(const FunctionCallbackInfo<Value>& args) {
10431078
} else {
10441079
CHECK_EQ(argc, 3);
10451080
FSReqWrapSync req_wrap_sync;
1081+
FS_SYNC_TRACE_BEGIN(fsync);
10461082
SyncCall(env, args[2], &req_wrap_sync, "fsync", uv_fs_fsync, fd);
1083+
FS_SYNC_TRACE_END(fsync);
10471084
}
10481085
}
10491086

@@ -1063,7 +1100,9 @@ static void Unlink(const FunctionCallbackInfo<Value>& args) {
10631100
} else {
10641101
CHECK_EQ(argc, 3);
10651102
FSReqWrapSync req_wrap_sync;
1103+
FS_SYNC_TRACE_BEGIN(unlink);
10661104
SyncCall(env, args[2], &req_wrap_sync, "unlink", uv_fs_unlink, *path);
1105+
FS_SYNC_TRACE_END(unlink);
10671106
}
10681107
}
10691108

@@ -1083,8 +1122,10 @@ static void RMDir(const FunctionCallbackInfo<Value>& args) {
10831122
} else { // rmdir(path, undefined, ctx)
10841123
CHECK_EQ(argc, 3);
10851124
FSReqWrapSync req_wrap_sync;
1125+
FS_SYNC_TRACE_BEGIN(rmdir);
10861126
SyncCall(env, args[2], &req_wrap_sync, "rmdir",
10871127
uv_fs_rmdir, *path);
1128+
FS_SYNC_TRACE_END(rmdir);
10881129
}
10891130
}
10901131

@@ -1107,8 +1148,10 @@ static void MKDir(const FunctionCallbackInfo<Value>& args) {
11071148
} else { // mkdir(path, mode, undefined, ctx)
11081149
CHECK_EQ(argc, 4);
11091150
FSReqWrapSync req_wrap_sync;
1151+
FS_SYNC_TRACE_BEGIN(mkdir);
11101152
SyncCall(env, args[3], &req_wrap_sync, "mkdir",
11111153
uv_fs_mkdir, *path, mode);
1154+
FS_SYNC_TRACE_END(mkdir);
11121155
}
11131156
}
11141157

@@ -1130,8 +1173,10 @@ static void RealPath(const FunctionCallbackInfo<Value>& args) {
11301173
} else { // realpath(path, encoding, undefined, ctx)
11311174
CHECK_EQ(argc, 4);
11321175
FSReqWrapSync req_wrap_sync;
1176+
FS_SYNC_TRACE_BEGIN(realpath);
11331177
int err = SyncCall(env, args[3], &req_wrap_sync, "realpath",
11341178
uv_fs_realpath, *path);
1179+
FS_SYNC_TRACE_END(realpath);
11351180
if (err < 0) {
11361181
return; // syscall failed, no need to continue, error info is in ctx
11371182
}
@@ -1171,8 +1216,10 @@ static void ReadDir(const FunctionCallbackInfo<Value>& args) {
11711216
} else { // readdir(path, encoding, undefined, ctx)
11721217
CHECK_EQ(argc, 4);
11731218
FSReqWrapSync req_wrap_sync;
1219+
FS_SYNC_TRACE_BEGIN(readdir);
11741220
int err = SyncCall(env, args[3], &req_wrap_sync, "scandir",
11751221
uv_fs_scandir, *path, 0 /*flags*/);
1222+
FS_SYNC_TRACE_END(readdir);
11761223
if (err < 0) {
11771224
return; // syscall failed, no need to continue, error info is in ctx
11781225
}
@@ -1255,8 +1302,10 @@ static void Open(const FunctionCallbackInfo<Value>& args) {
12551302
} else { // open(path, flags, mode, undefined, ctx)
12561303
CHECK_EQ(argc, 5);
12571304
FSReqWrapSync req_wrap_sync;
1305+
FS_SYNC_TRACE_BEGIN(open);
12581306
int result = SyncCall(env, args[4], &req_wrap_sync, "open",
12591307
uv_fs_open, *path, flags, mode);
1308+
FS_SYNC_TRACE_END(open);
12601309
args.GetReturnValue().Set(result);
12611310
}
12621311
}
@@ -1283,8 +1332,10 @@ static void OpenFileHandle(const FunctionCallbackInfo<Value>& args) {
12831332
} else { // openFileHandle(path, flags, mode, undefined, ctx)
12841333
CHECK_EQ(argc, 5);
12851334
FSReqWrapSync req_wrap_sync;
1335+
FS_SYNC_TRACE_BEGIN(open);
12861336
int result = SyncCall(env, args[4], &req_wrap_sync, "open",
12871337
uv_fs_open, *path, flags, mode);
1338+
FS_SYNC_TRACE_END(open);
12881339
if (result < 0) {
12891340
return; // syscall failed, no need to continue, error info is in ctx
12901341
}
@@ -1317,8 +1368,10 @@ static void CopyFile(const FunctionCallbackInfo<Value>& args) {
13171368
} else { // copyFile(src, dest, flags, undefined, ctx)
13181369
CHECK_EQ(argc, 5);
13191370
FSReqWrapSync req_wrap_sync;
1371+
FS_SYNC_TRACE_BEGIN(copyfile);
13201372
SyncCall(env, args[4], &req_wrap_sync, "copyfile",
13211373
uv_fs_copyfile, *src, *dest, flags);
1374+
FS_SYNC_TRACE_END(copyfile);
13221375
}
13231376
}
13241377

@@ -1368,8 +1421,10 @@ static void WriteBuffer(const FunctionCallbackInfo<Value>& args) {
13681421
} else { // write(fd, buffer, off, len, pos, undefined, ctx)
13691422
CHECK_EQ(argc, 7);
13701423
FSReqWrapSync req_wrap_sync;
1424+
FS_SYNC_TRACE_BEGIN(write);
13711425
int bytesWritten = SyncCall(env, args[6], &req_wrap_sync, "write",
13721426
uv_fs_write, fd, &uvbuf, 1, pos);
1427+
FS_SYNC_TRACE_END(write, "bytesWritten", bytesWritten);
13731428
args.GetReturnValue().Set(bytesWritten);
13741429
}
13751430
}
@@ -1411,8 +1466,10 @@ static void WriteBuffers(const FunctionCallbackInfo<Value>& args) {
14111466
} else { // writeBuffers(fd, chunks, pos, undefined, ctx)
14121467
CHECK_EQ(argc, 5);
14131468
FSReqWrapSync req_wrap_sync;
1469+
FS_SYNC_TRACE_BEGIN(write);
14141470
int bytesWritten = SyncCall(env, args[4], &req_wrap_sync, "write",
14151471
uv_fs_write, fd, *iovs, iovs.length(), pos);
1472+
FS_SYNC_TRACE_END(write, "bytesWritten", bytesWritten);
14161473
args.GetReturnValue().Set(bytesWritten);
14171474
}
14181475
}
@@ -1503,8 +1560,10 @@ static void WriteString(const FunctionCallbackInfo<Value>& args) {
15031560
buf = *stack_buffer;
15041561
}
15051562
uv_buf_t uvbuf = uv_buf_init(buf, len);
1563+
FS_SYNC_TRACE_BEGIN(write);
15061564
int bytesWritten = SyncCall(env, args[5], &req_wrap_sync, "write",
15071565
uv_fs_write, fd, &uvbuf, 1, pos);
1566+
FS_SYNC_TRACE_END(write, "bytesWritten", bytesWritten);
15081567
args.GetReturnValue().Set(bytesWritten);
15091568
}
15101569
}
@@ -1556,8 +1615,10 @@ static void Read(const FunctionCallbackInfo<Value>& args) {
15561615
} else { // read(fd, buffer, offset, len, pos, undefined, ctx)
15571616
CHECK_EQ(argc, 7);
15581617
FSReqWrapSync req_wrap_sync;
1618+
FS_SYNC_TRACE_BEGIN(read);
15591619
const int bytesRead = SyncCall(env, args[6], &req_wrap_sync, "read",
15601620
uv_fs_read, fd, &uvbuf, 1, pos);
1621+
FS_SYNC_TRACE_END(read, "bytesRead", bytesRead);
15611622
args.GetReturnValue().Set(bytesRead);
15621623
}
15631624
}
@@ -1585,8 +1646,10 @@ static void Chmod(const FunctionCallbackInfo<Value>& args) {
15851646
} else { // chmod(path, mode, undefined, ctx)
15861647
CHECK_EQ(argc, 4);
15871648
FSReqWrapSync req_wrap_sync;
1649+
FS_SYNC_TRACE_BEGIN(chmod);
15881650
SyncCall(env, args[3], &req_wrap_sync, "chmod",
15891651
uv_fs_chmod, *path, mode);
1652+
FS_SYNC_TRACE_END(chmod);
15901653
}
15911654
}
15921655

@@ -1613,8 +1676,10 @@ static void FChmod(const FunctionCallbackInfo<Value>& args) {
16131676
} else { // fchmod(fd, mode, undefined, ctx)
16141677
CHECK_EQ(argc, 4);
16151678
FSReqWrapSync req_wrap_sync;
1679+
FS_SYNC_TRACE_BEGIN(fchmod);
16161680
SyncCall(env, args[3], &req_wrap_sync, "fchmod",
16171681
uv_fs_fchmod, fd, mode);
1682+
FS_SYNC_TRACE_END(fchmod);
16181683
}
16191684
}
16201685

@@ -1644,8 +1709,10 @@ static void Chown(const FunctionCallbackInfo<Value>& args) {
16441709
} else { // chown(path, uid, gid, undefined, ctx)
16451710
CHECK_EQ(argc, 5);
16461711
FSReqWrapSync req_wrap_sync;
1712+
FS_SYNC_TRACE_BEGIN(chown);
16471713
SyncCall(env, args[4], &req_wrap_sync, "chown",
16481714
uv_fs_chown, *path, uid, gid);
1715+
FS_SYNC_TRACE_END(chown);
16491716
}
16501717
}
16511718

@@ -1675,8 +1742,10 @@ static void FChown(const FunctionCallbackInfo<Value>& args) {
16751742
} else { // fchown(fd, uid, gid, undefined, ctx)
16761743
CHECK_EQ(argc, 5);
16771744
FSReqWrapSync req_wrap_sync;
1745+
FS_SYNC_TRACE_BEGIN(fchown);
16781746
SyncCall(env, args[4], &req_wrap_sync, "fchown",
16791747
uv_fs_fchown, fd, uid, gid);
1748+
FS_SYNC_TRACE_END(fchown);
16801749
}
16811750
}
16821751

@@ -1703,8 +1772,10 @@ static void UTimes(const FunctionCallbackInfo<Value>& args) {
17031772
} else { // utimes(path, atime, mtime, undefined, ctx)
17041773
CHECK_EQ(argc, 5);
17051774
FSReqWrapSync req_wrap_sync;
1775+
FS_SYNC_TRACE_BEGIN(utimes);
17061776
SyncCall(env, args[4], &req_wrap_sync, "utime",
17071777
uv_fs_utime, *path, atime, mtime);
1778+
FS_SYNC_TRACE_END(utimes);
17081779
}
17091780
}
17101781

@@ -1730,8 +1801,10 @@ static void FUTimes(const FunctionCallbackInfo<Value>& args) {
17301801
} else { // futimes(fd, atime, mtime, undefined, ctx)
17311802
CHECK_EQ(argc, 5);
17321803
FSReqWrapSync req_wrap_sync;
1804+
FS_SYNC_TRACE_BEGIN(futimes);
17331805
SyncCall(env, args[4], &req_wrap_sync, "futime",
17341806
uv_fs_futime, fd, atime, mtime);
1807+
FS_SYNC_TRACE_END(futimes);
17351808
}
17361809
}
17371810

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

17601835
Local<Value> error;

‎src/tracing/trace_event_common.h

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -271,6 +271,9 @@
271271
// does nothing.
272272
// - category and name strings must have application lifetime (statics or
273273
// literals). They may not include " chars.
274+
#define TRACE_EVENT_BEGIN(category_group, name, ...) \
275+
INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category_group, name, \
276+
TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__)
274277
#define TRACE_EVENT_BEGIN0(category_group, name) \
275278
INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_BEGIN, category_group, name, \
276279
TRACE_EVENT_FLAG_NONE)
@@ -327,6 +330,9 @@
327330
// is not enabled, then this does nothing.
328331
// - category and name strings must have application lifetime (statics or
329332
// literals). They may not include " chars.
333+
#define TRACE_EVENT_END(category_group, name, ...) \
334+
INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category_group, name, \
335+
TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__)
330336
#define TRACE_EVENT_END0(category_group, name) \
331337
INTERNAL_TRACE_EVENT_ADD(TRACE_EVENT_PHASE_END, category_group, name, \
332338
TRACE_EVENT_FLAG_NONE)

0 commit comments

Comments
 (0)