Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
43 changes: 43 additions & 0 deletions benchmark/util/log.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,43 @@
'use strict';

const common = require('../common.js');
const util = require('util');

const bench = common.createBenchmark(main, {
method: ['simple_string', 'object_simple', 'object_complex'],
n: [1e4],
});

function main({ n, method }) {
const complexObject = {
name: 'test',
value: 123,
nested: {
array: [1, 2, 3, 4, 5],
boolean: true,
null: null,
},
};

bench.start();

switch (method) {
case 'simple_string':
for (let i = 0; i < n; i++) {
util.log('Hello World');
}
break;
case 'object_simple':
for (let i = 0; i < n; i++) {
util.log('Number:', i, 'Boolean:', true);
}
break;
case 'object_complex':
for (let i = 0; i < n; i++) {
util.log('Object:', complexObject);
}
break;
}

bench.end(n);
}
81 changes: 81 additions & 0 deletions doc/api/util.md
Original file line number Diff line number Diff line change
Expand Up @@ -1574,6 +1574,87 @@ inspect.defaultOptions.maxArrayLength = null;
console.log(arr); // logs the full array
```

## `util.log([...args])`

<!-- YAML
added: REPLACEME
-->

* `...args` {any}

A high-performance logging function optimized for scenarios where output is
redirected to files or pipes. The `util.log()` method formats its arguments
using [`util.format()`][] and writes the result to `stdout` with a trailing
newline.

```mjs
import { log } from 'node:util';

log('Hello', 'World');
// Prints: Hello World

log('User %s logged in', 'alice');
// Prints: User alice logged in
```

```cjs
const { log } = require('node:util');

log('Hello', 'World');
// Prints: Hello World
```

### Performance characteristics

The behavior differs based on the output destination:

* **TTY (interactive terminal)**: Synchronous writes for immediate visibility
* **Pipe/File (redirected output)**: Asynchronous buffering for performance
* 16KB buffer size
* 10ms flush interval
* Automatic flush on `process.beforeExit`

This makes `util.log()` ideal for high-frequency logging when output is
redirected, while maintaining the same behavior as `console.log()` for
interactive use.

```mjs
import { log } from 'node:util';

// High-frequency logging example
// When redirected (node script.js > output.log):
// - Buffered and batched for better performance
// When run in terminal:
// - Immediate output, same as console.log()

for (let i = 0; i < 10000; i++) {
log('Processing item', i);
}
```

### When to use `util.log()` vs `console.log()`

Use `util.log()` when:

* You have high-frequency logging (e.g., logging every request in a server)
* Output is redirected to files or pipes
* You want to reduce CPU usage from logging overhead

Use `console.log()` when:

* You need guaranteed immediate output before `process.exit()`
* You're debugging and need synchronous behavior
* You want consistency with browser JavaScript

**Performance impact**: In high-frequency logging scenarios with redirected
output, `util.log()` can significantly reduce logging overhead compared to
`console.log()` through asynchronous buffering and batched writes.

**Important**: Messages logged immediately before `process.exit()` may not be
written when output is buffered. Use `console.log()` for critical final
messages, or avoid calling `process.exit()` directly (let the process exit
naturally).

## `util.isDeepStrictEqual(val1, val2[, options])`

<!-- YAML
Expand Down
111 changes: 111 additions & 0 deletions lib/internal/util/log.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,111 @@
'use strict';

const {
ArrayPrototypeJoin,
ArrayPrototypePush,
} = primordials;

const { format } = require('internal/util/inspect');
const { guessHandleType } = internalBinding('util');
const {
clearTimeout,
setTimeout,
} = require('timers');

// Lazy-load binding to avoid circular dependencies
let binding;
function getBinding() {
binding ||= internalBinding('util');
return binding;
}

// Buffer configuration
const kBufferSize = 16384; // 16KB buffer
const kFlushInterval = 10; // Flush every 10ms
let pendingBuffer = [];
let pendingBytes = 0;
let flushTimer = null;
let isStdoutTTY = null;

// Check if stdout is TTY (only check once)
function isTTY() {
if (isStdoutTTY === null) {
// fd 1 is stdout
const type = guessHandleType(1);
// Type 1 is TTY, see node_util.cc GetUVHandleTypeCode
isStdoutTTY = type === 1;
}
return isStdoutTTY;
}

// Flush pending buffer to C++
function flush() {
if (flushTimer !== null) {
clearTimeout(flushTimer);
flushTimer = null;
}

if (pendingBuffer.length === 0) return;

const toWrite = pendingBuffer;
pendingBuffer = [];
pendingBytes = 0;

// Batch write: combine all strings and write once
// This is much faster than individual write calls
// Use join for better performance than string concatenation
const combined = ArrayPrototypeJoin(toWrite, '\n') + '\n';

getBinding().logRaw(combined);
}

// Schedule flush on next tick
function scheduleFlush() {
if (flushTimer !== null) return;

flushTimer = setTimeout(flush, kFlushInterval);
}

/**
* High-performance logging function optimized for async buffering.
* Unlike console.log, this function is designed for minimal overhead
* when output is redirected to files or pipes.
*
* Behavior:
* - TTY (terminal): Synchronous writes for immediate output
* - Pipe/File: Async buffering for better performance
* @param {...any} args - Values to log
*/
function log(...args) {
if (args.length === 0) {
getBinding().log('');
return;
}

// Format arguments using util.format for consistency
const formatted = format(...args);

// If stdout is a TTY, write immediately (sync)
// Otherwise, buffer for async writes (better performance)
if (isTTY()) {
getBinding().log(formatted);
} else {
// Async buffering path
ArrayPrototypePush(pendingBuffer, formatted);
pendingBytes += formatted.length;

// Flush if buffer is full
if (pendingBytes >= kBufferSize) {
flush();
} else {
scheduleFlush();
}
}
}

// Ensure buffer is flushed before exit
process.on('beforeExit', flush);

module.exports = {
log,
};
10 changes: 10 additions & 0 deletions lib/util.js
Original file line number Diff line number Diff line change
Expand Up @@ -79,6 +79,13 @@ function lazyUtilColors() {
utilColors ??= require('internal/util/colors');
return utilColors;
}

let utilLog;
function lazyUtilLog() {
utilLog ??= require('internal/util/log');
return utilLog;
}

const { getOptionValue } = require('internal/options');

const binding = internalBinding('util');
Expand Down Expand Up @@ -469,6 +476,9 @@ module.exports = {
callbackify,
debug: debuglog,
debuglog,
get log() {
return lazyUtilLog().log;
},
deprecate,
format,
styleText,
Expand Down
34 changes: 34 additions & 0 deletions src/node_util.cc
Original file line number Diff line number Diff line change
@@ -1,3 +1,5 @@
#include <climits>
#include <cmath>
#include "base_object-inl.h"
#include "node_dotenv.h"
#include "node_errors.h"
Expand Down Expand Up @@ -251,6 +253,34 @@ static void ParseEnv(const FunctionCallbackInfo<Value>& args) {
}
}

static void log(const FunctionCallbackInfo<Value>& args) {
Isolate* isolate = args.GetIsolate();

// JavaScript side sends pre-formatted string, just write it
CHECK_EQ(args.Length(), 1);
CHECK(args[0]->IsString());

Utf8Value str(isolate, args[0]);
std::string_view sv = str.ToStringView();

fwrite(sv.data(), 1, sv.length(), stdout);
fwrite("\n", 1, 1, stdout);
}

static void logRaw(const FunctionCallbackInfo<Value>& args) {
Isolate* isolate = args.GetIsolate();

// For batch writes - no newline added
CHECK_EQ(args.Length(), 1);
CHECK(args[0]->IsString());

Utf8Value str(isolate, args[0]);
std::string_view sv = str.ToStringView();

// Write raw string without adding newline
fwrite(sv.data(), 1, sv.length(), stdout);
}

static void GetCallSites(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);
Isolate* isolate = env->isolate();
Expand Down Expand Up @@ -453,6 +483,8 @@ void RegisterExternalReferences(ExternalReferenceRegistry* registry) {
registry->Register(GuessHandleType);
registry->Register(fast_guess_handle_type_);
registry->Register(ParseEnv);
registry->Register(log);
registry->Register(logRaw);
registry->Register(IsInsideNodeModules);
registry->Register(DefineLazyProperties);
registry->Register(DefineLazyPropertiesGetter);
Expand Down Expand Up @@ -555,6 +587,8 @@ void Initialize(Local<Object> target,
SetMethodNoSideEffect(context, target, "getCallSites", GetCallSites);
SetMethod(context, target, "sleep", Sleep);
SetMethod(context, target, "parseEnv", ParseEnv);
SetMethod(context, target, "log", log);
SetMethod(context, target, "logRaw", logRaw);

SetMethod(
context, target, "arrayBufferViewHasBuffer", ArrayBufferViewHasBuffer);
Expand Down
Loading
Loading