Skip to content

Commit 657db86

Browse files
committed
fs: add built-in fs.operation diagnostics channels
Add a built-in node:diagnostics_channel channel family for file system operations performed through node:fs and node:fs/promises. The channels are named tracing:fs.operation:start, :end, :asyncStart, :asyncEnd, and :error, and share an event payload carrying the operation name, the API (sync/callback/promise), path/dest/fd fields when applicable, plus result/error following TracingChannel conventions. Events are published from the internal shared file system layer rather than the JS wrappers, so captured function references still emit events. Signed-off-by: Matteo Collina <hello@matteocollina.com>
1 parent 347e266 commit 657db86

6 files changed

Lines changed: 435 additions & 0 deletions

File tree

doc/api/diagnostics_channel.md

Lines changed: 81 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1562,6 +1562,87 @@ passed to `console.warn()`.
15621562
Emitted when `console.error()` is called. Receives and array of the arguments
15631563
passed to `console.error()`.
15641564

1565+
#### Filesystem
1566+
1567+
> Stability: 1 - Experimental
1568+
1569+
These channels are emitted for file system operations performed through
1570+
`node:fs` and `node:fs/promises`. They form a [`TracingChannel`][] family named
1571+
`fs.operation`, so subscribers can use
1572+
[`diagnostics_channel.tracingChannel()`][] to subscribe to all events at once:
1573+
1574+
```mjs
1575+
import diagnostics_channel from 'node:diagnostics_channel';
1576+
1577+
const channel = diagnostics_channel.tracingChannel('fs.operation');
1578+
channel.subscribe({
1579+
start: (event) => console.log('start', event),
1580+
end: (event) => console.log('end', event),
1581+
error: (event) => console.log('error', event),
1582+
});
1583+
```
1584+
1585+
The events are published from the internal file system implementation, so they
1586+
are observed for every public `fs` operation regardless of whether the
1587+
function reference was captured before subscribing or whether the operation
1588+
uses the callback, promise, or synchronous API.
1589+
1590+
Each event carries an object with the following common fields:
1591+
1592+
* `operation` {string} A stable operation name, such as `open`, `read`,
1593+
`write`, `stat`, `readdir`, or `realpath`.
1594+
* `api` {string} The API that performed the operation: `'sync'`, `'callback'`,
1595+
or `'promise'`.
1596+
* `path` {string|undefined} The path argument for path-based operations, or
1597+
the source path for operations with a destination.
1598+
* `dest` {string|undefined} The destination argument for operations that
1599+
accept one, such as `rename`, `link`, `symlink`, or `copyFile`.
1600+
* `fd` {number|undefined} The file descriptor for operations that operate on
1601+
an existing file descriptor, such as `read`, `write`, `fsync`, or `close`.
1602+
1603+
Large read/write buffers are not copied into the event payload. The `start`
1604+
and `asyncStart` events carry no `result` or `error`; the `end` and `asyncEnd`
1605+
events carry the `result` of the operation, and the `error` event carries the
1606+
`error`, following the [TracingChannel Channels][] conventions.
1607+
1608+
Operations performed through streams (`fs.createReadStream` and
1609+
`fs.createWriteStream`) and most `FileHandle` methods are not covered by this
1610+
channel family, and may not emit the full set of events.
1611+
1612+
##### Event: `'tracing:fs.operation:start'`
1613+
1614+
Emitted synchronously when an operation begins, before the operation is
1615+
submitted. For synchronous operations this is followed by `end` (or `error`);
1616+
for asynchronous operations it is followed by `end` and then `asyncStart`/
1617+
`asyncEnd` (or `error`).
1618+
1619+
##### Event: `'tracing:fs.operation:end'`
1620+
1621+
* `result` {any} The result of the operation.
1622+
1623+
Emitted when the operation completes. For synchronous operations this carries
1624+
the operation `result`; for asynchronous operations it is emitted when the
1625+
operation is submitted and carries no `result` (the `result` is delivered on
1626+
the `asyncEnd` event).
1627+
1628+
##### Event: `'tracing:fs.operation:asyncStart'`
1629+
1630+
Emitted when the asynchronous work for an operation begins (when the
1631+
completion callback is invoked).
1632+
1633+
##### Event: `'tracing:fs.operation:asyncEnd'`
1634+
1635+
* `result` {any} The result of the operation.
1636+
1637+
Emitted when the asynchronous work for an operation completes, carrying the
1638+
operation `result`.
1639+
1640+
##### Event: `'tracing:fs.operation:error'`
1641+
1642+
* `error` {Error} The error that caused the operation to fail.
1643+
1644+
Emitted when an operation fails.
1645+
15651646
#### HTTP
15661647

15671648
> Stability: 1 - Experimental

src/env_properties.h

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -87,6 +87,7 @@
8787
V(allow_bare_named_params_string, "allowBareNamedParameters") \
8888
V(allow_unknown_named_params_string, "allowUnknownNamedParameters") \
8989
V(alpn_callback_string, "ALPNCallback") \
90+
V(api_string, "api") \
9091
V(args_string, "args") \
9192
V(arguments_string, "arguments") \
9293
V(async_ids_stack_string, "async_ids_stack") \
@@ -293,6 +294,7 @@
293294
V(onwrite_string, "onwrite") \
294295
V(ongracefulclosecomplete_string, "ongracefulclosecomplete") \
295296
V(openssl_error_stack, "opensslErrorStack") \
297+
V(operation_string, "operation") \
296298
V(operationerror_string, "OperationError") \
297299
V(options_string, "options") \
298300
V(original_string, "original") \

src/node_file-inl.h

Lines changed: 59 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -220,6 +220,7 @@ FSReqPromise<AliasedBufferT>::FSReqPromise(BindingData* binding_data,
220220
template <typename AliasedBufferT>
221221
void FSReqPromise<AliasedBufferT>::Reject(v8::Local<v8::Value> reject) {
222222
finished_ = true;
223+
PublishFSOpCompletionEvent(this, FSOperationChannel::kError, "error", reject);
223224
v8::HandleScope scope(env()->isolate());
224225
InternalCallbackScope callback_scope(this);
225226
v8::Local<v8::Value> value;
@@ -238,6 +239,8 @@ void FSReqPromise<AliasedBufferT>::Reject(v8::Local<v8::Value> reject) {
238239
template <typename AliasedBufferT>
239240
void FSReqPromise<AliasedBufferT>::Resolve(v8::Local<v8::Value> value) {
240241
finished_ = true;
242+
PublishFSOpCompletionEvent(this, FSOperationChannel::kAsyncEnd, "result",
243+
value);
241244
v8::HandleScope scope(env()->isolate());
242245
InternalCallbackScope callback_scope(this);
243246
v8::Local<v8::Value> val;
@@ -303,6 +306,7 @@ FSReqBase* GetReqWrap(const v8::FunctionCallbackInfo<v8::Value>& args,
303306
result =
304307
FSReqPromise<AliasedFloat64Array>::New(binding_data, use_bigint);
305308
}
309+
result->set_is_promise(true);
306310
}
307311
}
308312
if (result != nullptr) {
@@ -320,13 +324,32 @@ FSReqBase* AsyncDestCall(Environment* env, FSReqBase* req_wrap,
320324
Func fn, Args... fn_args) {
321325
CHECK_NOT_NULL(req_wrap);
322326
req_wrap->Init(syscall, dest, len, enc);
327+
BindingData* binding = req_wrap->binding_data();
328+
const char* api = req_wrap->is_promise() ? "promise" : "callback";
329+
std::string dest_str;
330+
if (binding != nullptr) {
331+
if (req_wrap->data() != nullptr) dest_str = req_wrap->data();
332+
PublishFSOperationEvent(binding, env, FSOperationChannel::kStart, syscall,
333+
api, std::string(), dest_str, -1, nullptr,
334+
v8::Local<v8::Value>());
335+
}
323336
int err = req_wrap->Dispatch(fn, fn_args..., after);
324337
if (err < 0) {
325338
uv_fs_t* uv_req = req_wrap->req();
326339
uv_req->result = err;
327340
uv_req->path = nullptr;
328341
after(uv_req); // after may delete req_wrap if there is an error
329342
req_wrap = nullptr;
343+
} else if (binding != nullptr) {
344+
std::string path;
345+
if (req_wrap->req()->path != nullptr) path = req_wrap->req()->path;
346+
int fd = -1;
347+
if (OperationUsesFd(req_wrap->req()->fs_type)) fd = req_wrap->req()->file;
348+
req_wrap->set_op_path(path);
349+
req_wrap->set_fd(fd);
350+
PublishFSOperationEvent(binding, env, FSOperationChannel::kEnd, syscall,
351+
api, path, dest_str, fd, nullptr,
352+
v8::Local<v8::Value>());
330353
}
331354
return req_wrap;
332355
}
@@ -381,7 +404,43 @@ int SyncCallAndThrowIf(Predicate should_throw,
381404
Func fn,
382405
Args... args) {
383406
env->PrintSyncTrace();
407+
BindingData* binding = Realm::GetBindingData<BindingData>(env->context());
408+
std::string path;
409+
std::string dest;
410+
if (binding != nullptr) {
411+
if (req_wrap->path_p != nullptr) path = req_wrap->path_p;
412+
if (req_wrap->dest_p != nullptr) dest = req_wrap->dest_p;
413+
PublishFSOperationEvent(binding, env, FSOperationChannel::kStart,
414+
req_wrap->syscall_p, "sync", path, dest, -1,
415+
nullptr, v8::Local<v8::Value>());
416+
}
384417
int result = fn(nullptr, &(req_wrap->req), args..., nullptr);
418+
if (binding != nullptr) {
419+
int fd = -1;
420+
if (OperationUsesFd(req_wrap->req.fs_type)) fd = req_wrap->req.file;
421+
if (should_throw(result)) {
422+
v8::Local<v8::Value> error = UVException(env->isolate(),
423+
result,
424+
req_wrap->syscall_p,
425+
nullptr,
426+
req_wrap->path_p,
427+
req_wrap->dest_p);
428+
PublishFSOperationEvent(binding, env, FSOperationChannel::kError,
429+
req_wrap->syscall_p, "sync", path, dest, fd,
430+
"error", error);
431+
} else {
432+
PublishFSOperationEvent(binding,
433+
env,
434+
FSOperationChannel::kEnd,
435+
req_wrap->syscall_p,
436+
"sync",
437+
path,
438+
dest,
439+
fd,
440+
"result",
441+
v8::Integer::New(env->isolate(), result));
442+
}
443+
}
385444
if (should_throw(result)) {
386445
env->ThrowUVException(result,
387446
req_wrap->syscall_p,

src/node_file.cc

Lines changed: 123 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -87,6 +87,121 @@ using v8::TryCatch;
8787
using v8::Undefined;
8888
using v8::Value;
8989

90+
// Built-in tracing channel names for filesystem operations, one per
91+
// FSOperationChannel in node_file.h.
92+
const char* const kFSOperationChannelNames[kNumFSOperationChannels] = {
93+
"tracing:fs.operation:start",
94+
"tracing:fs.operation:end",
95+
"tracing:fs.operation:asyncStart",
96+
"tracing:fs.operation:asyncEnd",
97+
"tracing:fs.operation:error",
98+
};
99+
100+
void PublishFSOperationEvent(BindingData* binding,
101+
Environment* env,
102+
FSOperationChannel channel,
103+
const char* operation,
104+
const char* api,
105+
const std::string& path,
106+
const std::string& dest,
107+
int fd,
108+
const char* value_key,
109+
Local<Value> value) {
110+
const size_t index = static_cast<size_t>(channel);
111+
CHECK_LT(index, kNumFSOperationChannels);
112+
diagnostics_channel::Channel* ch = binding->fs_op_channels_[index];
113+
if (ch == nullptr) {
114+
ch = diagnostics_channel::Channel::Get(
115+
env, kFSOperationChannelNames[index]);
116+
binding->fs_op_channels_[index] = ch;
117+
}
118+
if (ch == nullptr || !ch->HasSubscribers()) {
119+
return;
120+
}
121+
122+
Isolate* isolate = env->isolate();
123+
HandleScope scope(isolate);
124+
Local<Context> context = env->context();
125+
Local<Object> obj = Object::New(isolate);
126+
obj->Set(context,
127+
env->operation_string(),
128+
String::NewFromUtf8(isolate, operation).ToLocalChecked())
129+
.Check();
130+
obj->Set(context, env->api_string(),
131+
String::NewFromUtf8(isolate, api).ToLocalChecked())
132+
.Check();
133+
if (!path.empty()) {
134+
obj->Set(context,
135+
env->path_string(),
136+
String::NewFromUtf8(isolate,
137+
path.data(),
138+
v8::NewStringType::kNormal,
139+
static_cast<int>(path.size()))
140+
.ToLocalChecked())
141+
.Check();
142+
}
143+
if (!dest.empty()) {
144+
obj->Set(context,
145+
env->dest_string(),
146+
String::NewFromUtf8(isolate,
147+
dest.data(),
148+
v8::NewStringType::kNormal,
149+
static_cast<int>(dest.size()))
150+
.ToLocalChecked())
151+
.Check();
152+
}
153+
if (fd != -1) {
154+
obj->Set(context, env->fd_string(), Integer::New(isolate, fd)).Check();
155+
}
156+
if (value_key != nullptr && !value.IsEmpty()) {
157+
obj->Set(context, OneByteString(isolate, value_key), value).Check();
158+
}
159+
ch->Publish(env, obj);
160+
}
161+
162+
void PublishFSOpCompletionEvent(FSReqBase* req_wrap,
163+
FSOperationChannel channel,
164+
const char* value_key,
165+
Local<Value> value) {
166+
BindingData* binding = req_wrap->binding_data();
167+
if (binding == nullptr) return;
168+
const char* api = req_wrap->is_promise() ? "promise" : "callback";
169+
std::string dest;
170+
if (req_wrap->data() != nullptr) dest = req_wrap->data();
171+
PublishFSOperationEvent(binding,
172+
req_wrap->env(),
173+
channel,
174+
req_wrap->syscall(),
175+
api,
176+
req_wrap->op_path(),
177+
dest,
178+
req_wrap->fd(),
179+
value_key,
180+
value);
181+
}
182+
183+
// Returns true if the libuv fs request type operates on an existing file
184+
// descriptor (as opposed to taking a path). These are the request types whose
185+
// `file` field holds the input descriptor.
186+
bool OperationUsesFd(uv_fs_type fs_type) {
187+
switch (fs_type) {
188+
case UV_FS_CLOSE:
189+
case UV_FS_READ:
190+
case UV_FS_WRITE:
191+
case UV_FS_FSTAT:
192+
case UV_FS_FTRUNCATE:
193+
case UV_FS_FDATASYNC:
194+
case UV_FS_FSYNC:
195+
case UV_FS_FUTIME:
196+
case UV_FS_FCHMOD:
197+
case UV_FS_FCHOWN:
198+
case UV_FS_SENDFILE:
199+
return true;
200+
default:
201+
return false;
202+
}
203+
}
204+
90205
#ifndef S_ISDIR
91206
#define S_ISDIR(mode) (((mode)&S_IFMT) == S_IFDIR)
92207
#endif
@@ -221,6 +336,7 @@ FSReqBase::~FSReqBase() = default;
221336

222337
void FSReqBase::MemoryInfo(MemoryTracker* tracker) const {
223338
tracker->TrackField("continuation_data", continuation_data_);
339+
tracker->TrackField("op_path", op_path_);
224340
}
225341

226342
// The FileHandle object wraps a file descriptor and will close it on garbage
@@ -728,6 +844,7 @@ int FileHandle::DoShutdown(ShutdownWrap* req_wrap) {
728844
}
729845

730846
void FSReqCallback::Reject(Local<Value> reject) {
847+
PublishFSOpCompletionEvent(this, FSOperationChannel::kError, "error", reject);
731848
MakeCallback(env()->oncomplete_string(), 1, &reject);
732849
}
733850

@@ -740,6 +857,8 @@ void FSReqCallback::ResolveStatFs(const uv_statfs_t* stat) {
740857
}
741858

742859
void FSReqCallback::Resolve(Local<Value> value) {
860+
PublishFSOpCompletionEvent(this, FSOperationChannel::kAsyncEnd, "result",
861+
value);
743862
Local<Value> argv[2]{Null(env()->isolate()), value};
744863
MakeCallback(env()->oncomplete_string(),
745864
value->IsUndefined() ? 1 : arraysize(argv),
@@ -762,6 +881,10 @@ FSReqAfterScope::FSReqAfterScope(FSReqBase* wrap, uv_fs_t* req)
762881
handle_scope_(wrap->env()->isolate()),
763882
context_scope_(wrap->env()->context()) {
764883
CHECK_EQ(wrap_->req(), req);
884+
// The async work for the operation has completed; the continuation window
885+
// begins here.
886+
PublishFSOpCompletionEvent(wrap, FSOperationChannel::kAsyncStart, nullptr,
887+
Local<Value>());
765888
}
766889

767890
FSReqAfterScope::~FSReqAfterScope() {

0 commit comments

Comments
 (0)