Skip to content

Commit 508ffc0

Browse files
committed
fs: add per-operation fs diagnostics channels
Add built-in node:diagnostics_channel channels for file system operations performed through node:fs and node:fs/promises. Each operation gets its own TracingChannel family named fs.<operation>, with channels tracing:fs.<operation>:start, :end, :asyncStart, :asyncEnd, and :error. The event payload carries 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 508ffc0

6 files changed

Lines changed: 443 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`. Each operation has its own
1571+
[`TracingChannel`][] family named `fs.<operation>`, where `<operation>` is a
1572+
stable operation name such as `open`, `read`, `write`, `stat`, `readdir`, or
1573+
`realpath`. Subscribers can use [`diagnostics_channel.tracingChannel()`][] to
1574+
subscribe to all events of a given operation at once:
1575+
1576+
```mjs
1577+
import diagnostics_channel from 'node:diagnostics_channel';
1578+
1579+
const channel = diagnostics_channel.tracingChannel('fs.open');
1580+
channel.subscribe({
1581+
start: (event) => console.log('start', event),
1582+
end: (event) => console.log('end', event),
1583+
error: (event) => console.log('error', event),
1584+
});
1585+
```
1586+
1587+
The events are published from the internal file system implementation, so they
1588+
are observed for every public `fs` operation regardless of whether the
1589+
function reference was captured before subscribing or whether the operation
1590+
uses the callback, promise, or synchronous API.
1591+
1592+
Each event carries an object with the following common fields:
1593+
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 these
1610+
channel families, 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: 1 addition & 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") \

‎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: 122 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -87,6 +87,120 @@ using v8::TryCatch;
8787
using v8::Undefined;
8888
using v8::Value;
8989

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

222336
void FSReqBase::MemoryInfo(MemoryTracker* tracker) const {
223337
tracker->TrackField("continuation_data", continuation_data_);
338+
tracker->TrackField("op_path", op_path_);
224339
}
225340

226341
// The FileHandle object wraps a file descriptor and will close it on garbage
@@ -728,6 +843,7 @@ int FileHandle::DoShutdown(ShutdownWrap* req_wrap) {
728843
}
729844

730845
void FSReqCallback::Reject(Local<Value> reject) {
846+
PublishFSOpCompletionEvent(this, FSOperationChannel::kError, "error", reject);
731847
MakeCallback(env()->oncomplete_string(), 1, &reject);
732848
}
733849

@@ -740,6 +856,8 @@ void FSReqCallback::ResolveStatFs(const uv_statfs_t* stat) {
740856
}
741857

742858
void FSReqCallback::Resolve(Local<Value> value) {
859+
PublishFSOpCompletionEvent(this, FSOperationChannel::kAsyncEnd, "result",
860+
value);
743861
Local<Value> argv[2]{Null(env()->isolate()), value};
744862
MakeCallback(env()->oncomplete_string(),
745863
value->IsUndefined() ? 1 : arraysize(argv),
@@ -762,6 +880,10 @@ FSReqAfterScope::FSReqAfterScope(FSReqBase* wrap, uv_fs_t* req)
762880
handle_scope_(wrap->env()->isolate()),
763881
context_scope_(wrap->env()->context()) {
764882
CHECK_EQ(wrap_->req(), req);
883+
// The async work for the operation has completed; the continuation window
884+
// begins here.
885+
PublishFSOpCompletionEvent(wrap, FSOperationChannel::kAsyncStart, nullptr,
886+
Local<Value>());
765887
}
766888

767889
FSReqAfterScope::~FSReqAfterScope() {

0 commit comments

Comments
 (0)