Skip to content

Commit d9ff02c

Browse files
committed
lib: create util.log function
1 parent 0eda17b commit d9ff02c

File tree

6 files changed

+401
-0
lines changed

6 files changed

+401
-0
lines changed

benchmark/util/log.js

Lines changed: 43 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,43 @@
1+
'use strict';
2+
3+
const common = require('../common.js');
4+
const util = require('util');
5+
6+
const bench = common.createBenchmark(main, {
7+
method: ['simple_string', 'object_simple', 'object_complex'],
8+
n: [1e4],
9+
});
10+
11+
function main({ n, method }) {
12+
const complexObject = {
13+
name: 'test',
14+
value: 123,
15+
nested: {
16+
array: [1, 2, 3, 4, 5],
17+
boolean: true,
18+
null: null,
19+
},
20+
};
21+
22+
bench.start();
23+
24+
switch (method) {
25+
case 'simple_string':
26+
for (let i = 0; i < n; i++) {
27+
util.log('Hello World');
28+
}
29+
break;
30+
case 'object_simple':
31+
for (let i = 0; i < n; i++) {
32+
util.log('Number:', i, 'Boolean:', true);
33+
}
34+
break;
35+
case 'object_complex':
36+
for (let i = 0; i < n; i++) {
37+
util.log('Object:', complexObject);
38+
}
39+
break;
40+
}
41+
42+
bench.end(n);
43+
}

doc/api/util.md

Lines changed: 81 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1574,6 +1574,87 @@ inspect.defaultOptions.maxArrayLength = null;
15741574
console.log(arr); // logs the full array
15751575
```
15761576

1577+
## `util.log([...args])`
1578+
1579+
<!-- YAML
1580+
added: REPLACEME
1581+
-->
1582+
1583+
* `...args` {any}
1584+
1585+
A high-performance logging function optimized for scenarios where output is
1586+
redirected to files or pipes. The `util.log()` method formats its arguments
1587+
using [`util.format()`][] and writes the result to `stdout` with a trailing
1588+
newline.
1589+
1590+
```mjs
1591+
import { log } from 'node:util';
1592+
1593+
log('Hello', 'World');
1594+
// Prints: Hello World
1595+
1596+
log('User %s logged in', 'alice');
1597+
// Prints: User alice logged in
1598+
```
1599+
1600+
```cjs
1601+
const { log } = require('node:util');
1602+
1603+
log('Hello', 'World');
1604+
// Prints: Hello World
1605+
```
1606+
1607+
### Performance characteristics
1608+
1609+
The behavior differs based on the output destination:
1610+
1611+
* **TTY (interactive terminal)**: Synchronous writes for immediate visibility
1612+
* **Pipe/File (redirected output)**: Asynchronous buffering for performance
1613+
* 16KB buffer size
1614+
* 10ms flush interval
1615+
* Automatic flush on `process.beforeExit`
1616+
1617+
This makes `util.log()` ideal for high-frequency logging when output is
1618+
redirected, while maintaining the same behavior as `console.log()` for
1619+
interactive use.
1620+
1621+
```mjs
1622+
import { log } from 'node:util';
1623+
1624+
// High-frequency logging example
1625+
// When redirected (node script.js > output.log):
1626+
// - Buffered and batched for better performance
1627+
// When run in terminal:
1628+
// - Immediate output, same as console.log()
1629+
1630+
for (let i = 0; i < 10000; i++) {
1631+
log('Processing item', i);
1632+
}
1633+
```
1634+
1635+
### When to use `util.log()` vs `console.log()`
1636+
1637+
Use `util.log()` when:
1638+
1639+
* You have high-frequency logging (e.g., logging every request in a server)
1640+
* Output is redirected to files or pipes
1641+
* You want to reduce CPU usage from logging overhead
1642+
1643+
Use `console.log()` when:
1644+
1645+
* You need guaranteed immediate output before `process.exit()`
1646+
* You're debugging and need synchronous behavior
1647+
* You want consistency with browser JavaScript
1648+
1649+
**Performance impact**: In high-frequency logging scenarios with redirected
1650+
output, `util.log()` can significantly reduce logging overhead compared to
1651+
`console.log()` through asynchronous buffering and batched writes.
1652+
1653+
**Important**: Messages logged immediately before `process.exit()` may not be
1654+
written when output is buffered. Use `console.log()` for critical final
1655+
messages, or avoid calling `process.exit()` directly (let the process exit
1656+
naturally).
1657+
15771658
## `util.isDeepStrictEqual(val1, val2[, options])`
15781659

15791660
<!-- YAML

lib/internal/util/log.js

Lines changed: 111 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,111 @@
1+
'use strict';
2+
3+
const {
4+
ArrayPrototypeJoin,
5+
ArrayPrototypePush,
6+
} = primordials;
7+
8+
const { format } = require('internal/util/inspect');
9+
const { guessHandleType } = internalBinding('util');
10+
const {
11+
clearTimeout,
12+
setTimeout,
13+
} = require('timers');
14+
15+
// Lazy-load binding to avoid circular dependencies
16+
let binding;
17+
function getBinding() {
18+
binding ||= internalBinding('util');
19+
return binding;
20+
}
21+
22+
// Buffer configuration
23+
const kBufferSize = 16384; // 16KB buffer
24+
const kFlushInterval = 10; // Flush every 10ms
25+
let pendingBuffer = [];
26+
let pendingBytes = 0;
27+
let flushTimer = null;
28+
let isStdoutTTY = null;
29+
30+
// Check if stdout is TTY (only check once)
31+
function isTTY() {
32+
if (isStdoutTTY === null) {
33+
// fd 1 is stdout
34+
const type = guessHandleType(1);
35+
// Type 1 is TTY, see node_util.cc GetUVHandleTypeCode
36+
isStdoutTTY = type === 1;
37+
}
38+
return isStdoutTTY;
39+
}
40+
41+
// Flush pending buffer to C++
42+
function flush() {
43+
if (flushTimer !== null) {
44+
clearTimeout(flushTimer);
45+
flushTimer = null;
46+
}
47+
48+
if (pendingBuffer.length === 0) return;
49+
50+
const toWrite = pendingBuffer;
51+
pendingBuffer = [];
52+
pendingBytes = 0;
53+
54+
// Batch write: combine all strings and write once
55+
// This is much faster than individual write calls
56+
// Use join for better performance than string concatenation
57+
const combined = ArrayPrototypeJoin(toWrite, '\n') + '\n';
58+
59+
getBinding().logRaw(combined);
60+
}
61+
62+
// Schedule flush on next tick
63+
function scheduleFlush() {
64+
if (flushTimer !== null) return;
65+
66+
flushTimer = setTimeout(flush, kFlushInterval);
67+
}
68+
69+
/**
70+
* High-performance logging function optimized for async buffering.
71+
* Unlike console.log, this function is designed for minimal overhead
72+
* when output is redirected to files or pipes.
73+
*
74+
* Behavior:
75+
* - TTY (terminal): Synchronous writes for immediate output
76+
* - Pipe/File: Async buffering for better performance
77+
* @param {...any} args - Values to log
78+
*/
79+
function log(...args) {
80+
if (args.length === 0) {
81+
getBinding().log('');
82+
return;
83+
}
84+
85+
// Format arguments using util.format for consistency
86+
const formatted = format(...args);
87+
88+
// If stdout is a TTY, write immediately (sync)
89+
// Otherwise, buffer for async writes (better performance)
90+
if (isTTY()) {
91+
getBinding().log(formatted);
92+
} else {
93+
// Async buffering path
94+
ArrayPrototypePush(pendingBuffer, formatted);
95+
pendingBytes += formatted.length;
96+
97+
// Flush if buffer is full
98+
if (pendingBytes >= kBufferSize) {
99+
flush();
100+
} else {
101+
scheduleFlush();
102+
}
103+
}
104+
}
105+
106+
// Ensure buffer is flushed before exit
107+
process.on('beforeExit', flush);
108+
109+
module.exports = {
110+
log,
111+
};

lib/util.js

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -79,6 +79,13 @@ function lazyUtilColors() {
7979
utilColors ??= require('internal/util/colors');
8080
return utilColors;
8181
}
82+
83+
let utilLog;
84+
function lazyUtilLog() {
85+
utilLog ??= require('internal/util/log');
86+
return utilLog;
87+
}
88+
8289
const { getOptionValue } = require('internal/options');
8390

8491
const binding = internalBinding('util');
@@ -469,6 +476,9 @@ module.exports = {
469476
callbackify,
470477
debug: debuglog,
471478
debuglog,
479+
get log() {
480+
return lazyUtilLog().log;
481+
},
472482
deprecate,
473483
format,
474484
styleText,

src/node_util.cc

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,8 @@
44
#include "node_external_reference.h"
55
#include "util-inl.h"
66
#include "v8-fast-api-calls.h"
7+
#include <cmath>
8+
#include <climits>
79

810
namespace node {
911
namespace util {
@@ -251,6 +253,34 @@ static void ParseEnv(const FunctionCallbackInfo<Value>& args) {
251253
}
252254
}
253255

256+
static void log(const FunctionCallbackInfo<Value>& args) {
257+
Isolate* isolate = args.GetIsolate();
258+
259+
// JavaScript side sends pre-formatted string, just write it
260+
CHECK_EQ(args.Length(), 1);
261+
CHECK(args[0]->IsString());
262+
263+
Utf8Value str(isolate, args[0]);
264+
std::string_view sv = str.ToStringView();
265+
266+
fwrite(sv.data(), 1, sv.length(), stdout);
267+
fwrite("\n", 1, 1, stdout);
268+
}
269+
270+
static void logRaw(const FunctionCallbackInfo<Value>& args) {
271+
Isolate* isolate = args.GetIsolate();
272+
273+
// For batch writes - no newline added
274+
CHECK_EQ(args.Length(), 1);
275+
CHECK(args[0]->IsString());
276+
277+
Utf8Value str(isolate, args[0]);
278+
std::string_view sv = str.ToStringView();
279+
280+
// Write raw string without adding newline
281+
fwrite(sv.data(), 1, sv.length(), stdout);
282+
}
283+
254284
static void GetCallSites(const FunctionCallbackInfo<Value>& args) {
255285
Environment* env = Environment::GetCurrent(args);
256286
Isolate* isolate = env->isolate();
@@ -453,6 +483,8 @@ void RegisterExternalReferences(ExternalReferenceRegistry* registry) {
453483
registry->Register(GuessHandleType);
454484
registry->Register(fast_guess_handle_type_);
455485
registry->Register(ParseEnv);
486+
registry->Register(log);
487+
registry->Register(logRaw);
456488
registry->Register(IsInsideNodeModules);
457489
registry->Register(DefineLazyProperties);
458490
registry->Register(DefineLazyPropertiesGetter);
@@ -555,6 +587,8 @@ void Initialize(Local<Object> target,
555587
SetMethodNoSideEffect(context, target, "getCallSites", GetCallSites);
556588
SetMethod(context, target, "sleep", Sleep);
557589
SetMethod(context, target, "parseEnv", ParseEnv);
590+
SetMethod(context, target, "log", log);
591+
SetMethod(context, target, "logRaw", logRaw);
558592

559593
SetMethod(
560594
context, target, "arrayBufferViewHasBuffer", ArrayBufferViewHasBuffer);

0 commit comments

Comments
 (0)