console.log 背后那点事儿

1,049 阅读3分钟

本篇是来自Node.js 与 HBase 通信的插曲篇。上周我在兴致勃勃地调试 HBase 客户端的时候,同事悄咪咪的在我背后说:你这不行,少用 console.log,这个是同步的,最好用 process.stdout.write 这个是异步的,然后还热心的给我发了一张 benchmark 的图。

1929857006.jpg

On my back say i cann`t。针对这个问题,咱要好好说下:

  1. 为什么性能差异这么大?
  2. 到底是什么步的?

本片源码基于 Node.js 12.16.3。

为什么性能差异这么大

console stdout 的本质

consolelib/internal/bootstrap/node.js 被绑定到全局边量中

exposeNamespace(global, 'console', createGlobalConsole(global.console));

console 源自internal/console/global

function createGlobalConsole(consoleFromVM) {
  const consoleFromNode =
    require('internal/console/global');
  return consoleFromNode;
}

globalConsole 初始化

const globalConsole = ObjectCreate({});
...
globalConsole[kBindStreamsLazy](process);
globalConsole[kBindProperties](true, 'auto');

// This is a legacy feature - the Console constructor is exposed on
// the global console instance.
globalConsole.Console = Console;

module.exports = globalConsole;

检索 kBindStreamsLazy 发现: console 源自 process

Console.prototype[kBindStreamsLazy] = function(object) {
  let stdout;
  let stderr;
  ObjectDefineProperties(this, {
    '_stdout': {
      enumerable: false,
      configurable: true,
      get() {
        if (!stdout) stdout = object.stdout;
        return stdout;
      },
      set(value) { stdout = value; }
    },
    '_stderr': {
      enumerable: false,
      configurable: true,
      get() {
        if (!stderr) { stderr = object.stderr; }
        return stderr;
      },
      set(value) { stderr = value; }
    }
  });
};

通过上面的代码可以明显发现,console 的 stdout === process.stdout ,可以执行下面代码求证

console.log(console._stdout === process.stdout); // true

差异来源

继续检索 console.log 的实现方式

  log(...args) {
    this[kWriteToConsole](kUseStdout, this[kFormatForStdout](args));
  },

kWriteToConsole

Console.prototype[kWriteToConsole] = function(streamSymbol, string) {
  const ignoreErrors = this._ignoreErrors;
  const groupIndent = this[kGroupIndent];

  const useStdout = streamSymbol === kUseStdout;
  const stream = useStdout ? this._stdout : this._stderr;  // 使用了 process.stdout
  const errorHandler = useStdout ?
    this._stdoutErrorHandler : this._stderrErrorHandler;

  if (groupIndent.length !== 0) {
    if (string.includes('\n')) {
      string = string.replace(/\n/g, `\n${groupIndent}`);
    }
    string = groupIndent + string;
  }
  string += '\n'; // 做了字符串运算

  if (ignoreErrors === false) return stream.write(string);

  // There may be an error occurring synchronously (e.g. for files or TTYs
  // on POSIX systems) or asynchronously (e.g. pipes on POSIX systems), so
  // handle both situations.
  try {
    // Add and later remove a noop error handler to catch synchronous errors.
    if (stream.listenerCount('error') === 0) // 做了函数调用
      stream.once('error', noop); // 添加一次 listener

    stream.write(string, errorHandler); // process.stdout.write 只干了这一行的事情
  } catch (e) {
    // Console is a debugging utility, so it swallowing errors is not desirable
    // even in edge cases such as low stack space.
    if (isStackOverflowError(e))
      throw e;
    // Sorry, there's no proper way to pass along the error here.
  } finally {
    stream.removeListener('error', noop); // 移除 listener
  }
};

通过上面的注释可以看到,在压测环节 process.stdout.write只执行了这一行代码,而 console.log则默默无闻做了很多事情,如下:

  1. 格式化 log 参数
  2. 处理 string
  3. 判断是否有 error handler
  4. 没有 error handler 则初始化
  5. 调用 process.stdout.write
  6. 移除 error handler

再次实现

bench.add('with stdout', () => {
	process.stdout.write('' + '\n'); // 模拟 string += '\n'
	process.stdout.listenerCount(); // 模拟 listenerCount 调用
})

仅仅模拟两处功能,两者的压测结果已经比较接近了。

到底是什么步的

脱离场景谈论什么步,是没有意义。翻开官方文档 Node.js 14.17.3 ,有这么一段话:

A note on process I/O#

process.stdout and process.stderr differ from other Node.js streams in important ways:

  1. They are used internally by console.log() and console.error(), respectively.
  2. Writes may be synchronous depending on what the stream is connected to and whether the system is Windows or POSIX:
  • Files: synchronous on Windows and POSIX
  • TTYs (Terminals): asynchronous on Windows, synchronous on POSIX
  • Pipes (and sockets): synchronous on Windows, asynchronous on POSIX

These behaviors are partly for historical reasons, as changing them would create backward incompatibility, but they are also expected by some users.

Synchronous writes avoid problems such as output written with console.log() or console.error() being unexpectedly interleaved, or not written at all if process.exit() is called before an asynchronous write completes. See process.exit() for more information.

  1. 同步还是异步,与使用方式和运行平台有关系
  2. 同步方式避免了很多问题

那当我们在 Linux 系统中使用 Node.js 运行下面代码的时候,process.stdout 是什么步?

console.log(process.stdout.isTTY); // true

根据文档的定义,上面的场景是 同步

翻下源码发现

process.stdout 定义在 lib/internal/bootstrap/switches/is_main_thread.js

defineStream('stdout', getStdout);

getStdout

function getStdout() {
  if (stdout) return stdout;
  stdout = createWritableStdioStream(1);
  return stdout;
}

createWritableStdioStream

function createWritableStdioStream(fd) {
  let stream;
  // Note stream._type is used for test-module-load-list.js
  switch (guessHandleType(fd)) {
    case 'TTY':
      const tty = require('tty');
      stream = new tty.WriteStream(fd);
      stream._type = 'tty';
      break;

    case 'FILE':
      const SyncWriteStream = require('internal/fs/sync_write_stream');
      stream = new SyncWriteStream(fd, { autoClose: false });
      stream._type = 'fs';
      break;

    case 'PIPE':
    case 'TCP':
      const net = require('net');

      // If fd is already being used for the IPC channel, libuv will return
      // an error when trying to use it again. In that case, create the socket
      // using the existing handle instead of the fd.
      if (process.channel && process.channel.fd === fd) {
        stream = new net.Socket({
          handle: process.channel,
          readable: false,
          writable: true
        });
      } else {
        stream = new net.Socket({
          fd,
          readable: false,
          writable: true
        });
      }

      stream._type = 'pipe';
      break;

    default:
      // Provide a dummy black-hole output for e.g. non-console
      // Windows applications.
      const { Writable } = require('stream');
      stream = new Writable({
        write(buf, enc, cb) {
          cb();
        }
      });
  }

  // For supporting legacy API we put the FD here.
  stream.fd = fd;

  stream._isStdio = true;

  return stream;
}

总结

本是同根生。

关注我的微信公众号"SUNTOPO WLOG",欢迎留言讨论,我会尽可能回复,感谢您的阅读。