console.log는 어떻게 동작할까?

서론

로그로 인해 Nodejs 서버가 느려졌던 경험이 있었습니다. 단순 로그만 찍었는데 왜 이런일이 발생하는 것인지 문득 궁금해져서 console.log('Hello World')를 호출하면 무슨 일이 일어나는지 자세히 파보았습니다.

단순해 보이는 이 한 줄의 코드는 실제로는 JavaScript 레벨부터 C++ 레벨, libuv, 그리고 시스템 호출까지 여러 레이어를 거쳐 실행됩니다. 이 글에서는 Node.js의 실제 소스 코드를 따라가며 console.log의 내부 동작을 완전히 파헤쳐보겠습니다.

---

1. 전체 실행 흐름 개요

console.log를 호출하면 다음과 같은 경로를 따라 실행됩니다:

사용자 코드: console.log('Hello World')
  ↓
lib/internal/console/constructor.js::consoleMethods.log()
  ↓
kFormatForStdout() - 인자 포맷팅
  ↓ (formatWithOptions 호출)
lib/internal/util/inspect.js::formatWithOptions()
  ↓
kWriteToConsole() - stream.write() 호출
  ↓
lib/internal/streams/writable.js - 버퍼 관리
  ↓
src/stream_base.cc::StreamBase::Write() - C++ 바인딩
  ↓
libuv::uv_write() - 이벤트 루프 통합
  ↓
write() syscall - 실제 I/O

각 단계에서 어떤 코드가 실행되는지 자세히 살펴보겠습니다.

---

2. JavaScript 레벨: console.log 진입점

2.1 console 객체의 생성

Node.js가 시작될 때 lib/internal/console/global.js에서 전역 console 객체를 생성합니다. 이 객체는 lib/internal/console/constructor.js의 Console 클래스 인스턴스입니다.

2.2 log() 메서드 구현

console.log는 lib/internal/console/constructor.js 파일의 consoleMethods 객체에 정의되어 있습니다:

  log(...args) {
    if (onLog.hasSubscribers) {
      onLog.publish(args);
    }
    this[kWriteToConsole](kUseStdout, this[kFormatForStdout](args));
  },

코드 분석:

1. diagnostics_channel 이벤트 발행: onLog.hasSubscribers가 true이면 diagnostics_channel을 통해 이벤트를 발행합니다. 이는 Node.js의 내부 모니터링 시스템에서 로그를 구독할 수 있게 합니다.

2. 포맷팅 및 쓰기:

   • this[kFormatForStdout](args): 인자를 포맷팅하여 문자열로 변환
   • this[kWriteToConsole](kUseStdout, ...): 포맷팅된 문자열을 stdout에 쓰기

이 두 단계가 console.log의 핵심입니다. 각각을 자세히 살펴보겠습니다.

---

3. 포맷팅 단계: kFormatForStdout

3.1 Fast Path vs Slow Path

포맷팅은 성능 최적화를 위해 두 가지 경로를 제공합니다:

  [kFormatForStdout]: {
    __proto__: null,
    ...consolePropAttributes,
    value: function(args) {
      if (args.length === 1) {
        // Fast path: single string, don't call format.
        // Avoids ReflectApply and validation overhead.
        const a0 = args[0];
        if (typeof a0 === 'string') {
          return a0;
        }
      }
      const opts = this[kGetInspectOptions](this._stdout);
      ArrayPrototypeUnshift(args, opts);
      return ReflectApply(formatWithOptions, null, args);
    },
  },

Fast Path (최적화 경로):

• 조건: 단일 인자이고 타입이 string인 경우
• 동작: 포맷팅을 완전히 스킵하고 원본 문자열을 그대로 반환
• 이유: ReflectApply 호출과 검증 오버헤드를 피할 수 있음

Slow Path (일반 경로):

• 조건: 여러 인자이거나 단일 인자라도 문자열이 아닌 경우
• 동작: formatWithOptions 함수를 호출하여 포맷팅 수행

3.2 inspect 옵션 결정

Slow Path로 진입하면 먼저 inspect 옵션을 결정합니다:

  [kGetInspectOptions]: {
    __proto__: null,
    ...consolePropAttributes,
    value: function(stream) {
      let color = this[kColorMode];
      if (color === 'auto') {
        color = lazyUtilColors().shouldColorize(stream);
      }

      const inspectOptionsMap = optionsMap.get(this);
      const options = inspectOptionsMap ? MapPrototypeGet(inspectOptionsMap, stream) : undefined;
      if (options) {
        if (options.colors === undefined) {
          options.colors = color;
        }
        return options;
      }

      return color ? kColorInspectOptions : kNoColorInspectOptions;
    },
  },

주요 로직:

1. 색상 모드 결정: colorMode가 'auto'이면 스트림이 TTY인지 확인하여 색상 사용 여부 결정
2. 사용자 정의 옵션 확인: inspectOptions가 설정되어 있으면 사용
3. 기본 옵션 반환: 색상 사용 여부에 따라 kColorInspectOptions 또는 kNoColorInspectOptions 반환

3.3 formatWithOptions 호출

포맷팅 옵션이 결정되면 formatWithOptions 함수를 호출합니다:

function formatWithOptions(inspectOptions, ...args) {
  validateObject(inspectOptions, 'inspectOptions', kValidateObjectAllowArray);
  return formatWithOptionsInternal(inspectOptions, args);
}

이 함수는 내부적으로 formatWithOptionsInternal을 호출합니다:

function formatWithOptionsInternal(inspectOptions, args) {
  const first = args[0];
  let a = 0;
  let str = '';
  let join = '';

  if (typeof first === 'string') {
    if (args.length === 1) {
      return first;
    }
    let tempStr;
    let lastPos = 0;

    for (let i = 0; i < first.length - 1; i++) {
      if (StringPrototypeCharCodeAt(first, i) === 37) { // '%'
        const nextChar = StringPrototypeCharCodeAt(first, ++i);
        if (a + 1 !== args.length) {
          switch (nextChar) {
            case 115: { // 's'
              const tempArg = args[++a];
              if (typeof tempArg === 'number') {
                tempStr = formatNumberNoColor(tempArg, inspectOptions);
              } else if (typeof tempArg === 'bigint') {
                tempStr = formatBigIntNoColor(tempArg, inspectOptions);
              } else if (typeof tempArg !== 'object' ||
                         tempArg === null ||
                         !hasBuiltInToString(tempArg)) {
                tempStr = String(tempArg);
              } else {
                tempStr = inspect(tempArg, inspectOptions);
              }
              // ... 나머지 포맷팅 로직
            }
            // ... 다른 포맷 지정자 처리
          }
        }
      }
    }
    // ... 포맷 문자열 처리
  }

  // 첫 번째 인자가 문자열이 아닌 경우
  for (let i = 0; i < args.length; i++) {
    if (i > 0) {
      str += join;
    }
    str += inspect(args[i], inspectOptions);
  }

  return str;
}

주요 동작:

1. 포맷 문자열 처리: 첫 번째 인자가 문자열이고 %s, %d 등의 포맷 지정자가 있으면 처리
2. inspect() 호출: 각 인자를 inspect() 함수로 문자열로 변환
3. 결합: 변환된 문자열들을 공백으로 결합

3.4 inspect() 함수: 객체를 문자열로 변환

inspect() 함수는 객체를 읽기 쉬운 문자열로 변환하는 핵심 함수입니다. 이 함수는 매우 복잡하며 수천 줄의 코드로 구성되어 있습니다.

주요 기능:

1. 타입별 포맷터: 객체 타입(Array, Object, Map, Set, Date 등)에 따라 다른 포맷터 사용
2. 순환 참조 감지: 순환 참조를 감지하고 [Circular]로 표시
3. 깊이 제한: depth 옵션에 따라 중첩 깊이 제한
4. 색상 코드 추가: TTY인 경우 ANSI 색상 코드 추가
5. 커스텀 inspect: 객체에 [util.inspect.custom] 심볼이 있으면 사용

예시:

const obj = { a: 1, b: { c: 2 } };
inspect(obj); 
// "{ a: 1, b: { c: 2 } }"

const circular = {};
circular.self = circular;
inspect(circular);
// "{ self: [Circular] }"

---

4. 쓰기 단계: kWriteToConsole

포맷팅이 완료되면 실제로 스트림에 쓰는 단계입니다:

  [kWriteToConsole]: {
    __proto__: null,
    ...consolePropAttributes,
    value: function(streamSymbol, string) {
      const ignoreErrors = this._ignoreErrors;
      const groupIndent = this[kGroupIndentationString];

      const useStdout = streamSymbol === kUseStdout;
      const stream = useStdout ? this._stdout : this._stderr;
      const errorHandler = useStdout ?
        this._stdoutErrorHandler : this._stderrErrorHandler;

      if (groupIndent.length !== 0) {
        if (StringPrototypeIncludes(string, '\n')) {
          string = RegExpPrototypeSymbolReplace(/\n/g, string, `\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);

        stream.write(string, errorHandler);
      } 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);
      }
    },
  },

단계별 분석:

1. 스트림 선택: streamSymbol에 따라 stdout 또는 stderr 선택
2. 그룹 인덴트 처리: console.group() 사용 시 인덴트 추가
3. 개행 추가: 모든 로그 끝에 \n 추가
4. 에러 핸들링:
   • 동기 에러: try-catch로 처리
   • 비동기 에러: error 이벤트 리스너로 처리
   • 매 호출마다 리스너 추가/제거 (오버헤드 발생)
5. stream.write() 호출: 실제 쓰기 작업 수행

에러 핸들링의 복잡성:

주석에서 볼 수 있듯이, 에러는 동기적으로 발생할 수도 있고(파일이나 TTY), 비동기적으로 발생할 수도 있습니다(파이프). 이를 모두 처리하기 위해:

• try-catch로 동기 에러 처리
• stream.once('error', noop)로 비동기 에러 처리
• finally 블록에서 리스너 제거

이 과정이 매 호출마다 반복되므로 오버헤드가 발생합니다.

---

5. Stream 레벨: 버퍼 관리와 백프레셔

5.1 Writable Stream 구조

stream.write()는 Node.js의 Writable Stream을 통해 처리됩니다. Writable Stream은 lib/internal/streams/writable.js에 구현되어 있습니다.

주요 구성 요소:

// lib/internal/streams/writable.js
function Writable(options) {
  // ...
  this._writableState = new WritableState(options, this);
  // ...
}

function WritableState(options, stream) {
  // ...
  this.objectMode = !!(options && options.objectMode);
  this.highWaterMark = getHighWaterMark(this, options, 'writable', this.objectMode);
  this.buffer = new BufferList();
  this.length = 0;
  // ...
}

버퍼 관리:

• buffer: 쓰기 대기 중인 데이터를 저장하는 버퍼
• length: 현재 버퍼에 있는 데이터의 총 길이
• highWaterMark: 버퍼가 가득 찬 것으로 간주되는 임계값

5.2 write() 메서드 구현

Writable Stream의 write() 메서드는 다음과 같이 동작합니다:

Writable.prototype.write = function(chunk, encoding, cb) {
  const state = this._writableState;
  
  // 인코딩 처리
  if (typeof encoding === 'function') {
    cb = encoding;
    encoding = null;
  }
  
  // 버퍼에 추가
  const ret = state.length < state.highWaterMark;
  if (!ret) {
    state.needDrain = true;
  }
  
  // _write() 호출
  if (state.sync) {
    process.nextTick(doWrite, stream, state, false, len, chunk, encoding, cb);
  } else {
    doWrite(stream, state, false, len, chunk, encoding, cb);
  }
  
  return ret;
};

백프레셔 처리:

• state.length < state.highWaterMark: 버퍼가 가득 차지 않았으면 true 반환
• 버퍼가 가득 차면 state.needDrain = true 설정하고 false 반환
• false를 반환받으면 더 이상 쓰지 않고 drain 이벤트를 기다려야 함

5.3 TTY vs 파이프/파일

출력 대상에 따라 동작 방식이 다릅니다:

TTY (터미널):

• process.stdout.isTTY === true
• 동기 I/O 가능: process.stdout._handle.writeSync() 직접 호출 가능
• 블로킹 가능: 이벤트 루프를 멈출 수 있음

파이프/파일:

• process.stdout.isTTY === false
• 비동기 I/O: libuv 이벤트 루프를 통해 처리
• 백프레셔 발생 시 버퍼링

---

6. C++ 레벨: StreamBase::Write

JavaScript 레벨의 stream.write()는 내부적으로 C++ 바인딩을 통해 처리됩니다. Node.js의 C++ 바인딩은 src/stream_base.cc에 구현되어 있습니다.

6.1 StreamBase::Write 구현

StreamWriteResult StreamBase::Write(uv_buf_t* bufs,
                                    size_t count,
                                    uv_stream_t* send_handle,
                                    v8::Local<v8::Object> req_wrap_obj,
                                    bool skip_try_write) {
  Environment* env = stream_env();
  int err;

  size_t total_bytes = 0;
  for (size_t i = 0; i < count; ++i) total_bytes += bufs[i].len;
  bytes_written_ += total_bytes;

  if (send_handle == nullptr && HasDoTryWrite() && !skip_try_write) {
    err = DoTryWrite(&bufs, &count);
    if (err != 0 || count == 0) {
      return StreamWriteResult{false, err, nullptr, total_bytes, {}};
    }
  }

  v8::HandleScope handle_scope(env->isolate());

  if (req_wrap_obj.IsEmpty()) {
    if (!env->write_wrap_template()
             ->NewInstance(env->context())
             .ToLocal(&req_wrap_obj)) {
      return StreamWriteResult{false, UV_EBUSY, nullptr, 0, {}};
    }
    StreamReq::ResetObject(req_wrap_obj);
  }

  AsyncHooks::DefaultTriggerAsyncIdScope trigger_scope(GetAsyncWrap());
  WriteWrap* req_wrap = CreateWriteWrap(req_wrap_obj);
  BaseObjectPtr<AsyncWrap> req_wrap_ptr(req_wrap->GetAsyncWrap());

  err = DoWrite(req_wrap, bufs, count, send_handle);
  bool async = err == 0;

  if (!async) {
    req_wrap->Dispose();
    req_wrap = nullptr;
  }

  const char* msg = Error();
  if (msg != nullptr) {
    if (req_wrap_obj
            ->Set(env->context(),
                  env->error_string(),
                  OneByteString(env->isolate(), msg))
            .IsNothing()) {
      return StreamWriteResult{false, UV_EBUSY, nullptr, 0, {}};
    }
    ClearError();
  }

  return StreamWriteResult{async, err, req_wrap, total_bytes, {}};
}

주요 단계:

1. 바이트 수 계산: 모든 버퍼의 총 바이트 수 계산
2. DoTryWrite 시도: 비동기 쓰기 전에 동기 쓰기를 시도
   • 성공하면 즉시 반환 (성능 최적화)
   • 실패하면 비동기 경로로 진행
3. WriteWrap 생성: 비동기 쓰기 요청을 래핑하는 객체 생성
4. DoWrite 호출: 실제 쓰기 작업 수행
5. 결과 반환: 동기/비동기 여부와 함께 결과 반환

6.2 DoTryWrite: 동기 쓰기 시도

DoTryWrite()는 비동기 쓰기 전에 동기 쓰기를 시도하는 최적화입니다:

// 의사 코드
int DoTryWrite(uv_buf_t** bufs, size_t* count) {
  // TTY인 경우 동기 쓰기 시도
  if (IsTTY()) {
    int err = uv_try_write(handle, *bufs, *count);
    if (err > 0) {
      // 일부 또는 전체가 쓰여짐
      // 남은 버퍼 업데이트
      return 0; // 성공
    }
  }
  return UV_EAGAIN; // 비동기로 처리 필요
}

최적화 효과:

• TTY 환경에서 작은 데이터는 동기적으로 즉시 쓰여짐
• 이벤트 루프를 거치지 않아 오버헤드 감소
• 큰 데이터나 파이프는 여전히 비동기로 처리

---

7. libuv 레벨: 이벤트 루프 통합

libuv는 Node.js의 비동기 I/O 라이브러리입니다. C++ 레벨에서 비동기 쓰기가 필요하면 libuv를 통해 처리됩니다.

7.1 uv_write() 호출

// deps/uv/src/unix/stream.c (의사 코드)
int uv_write(uv_write_t* req,
             uv_stream_t* handle,
             const uv_buf_t bufs[],
             unsigned int nbufs,
             uv_write_cb cb) {
  // 쓰기 요청을 큐에 추가
  QUEUE_INSERT_TAIL(&handle->write_queue, &req->queue);
  
  // 이벤트 루프에 등록
  uv__io_start(handle->loop, &handle->io_watcher, POLLOUT);
  
  return 0;
}

주요 동작:

1. 요청 큐에 추가: 쓰기 요청을 스트림의 쓰기 큐에 추가
2. 이벤트 루프 등록: 쓰기 가능할 때 알림을 받기 위해 이벤트 루프에 등록
3. 비동기 처리: 실제 쓰기는 이벤트 루프의 다음 틱에서 처리

7.2 이벤트 루프에서의 처리

이벤트 루프는 다음과 같이 쓰기 요청을 처리합니다:

// 이벤트 루프의 쓰기 단계 (의사 코드)
void uv__stream_io(uv_loop_t* loop, uv__io_t* w, unsigned int events) {
  if (events & POLLOUT) {
    // 쓰기 가능
    uv__stream_flush_write_queue(stream);
  }
}

void uv__stream_flush_write_queue(uv_stream_t* stream) {
  while (!QUEUE_EMPTY(&stream->write_queue)) {
    uv_write_t* req = QUEUE_HEAD(&stream->write_queue);
    
    // 실제 시스템 호출
    ssize_t n = write(stream->fd, req->bufs, req->nbufs);
    
    if (n > 0) {
      // 성공: 콜백 호출
      req->cb(req, 0);
      QUEUE_REMOVE(&req->queue);
    } else if (n == -1 && errno == EAGAIN) {
      // 다시 시도 필요: 다음 틱에서 처리
      break;
    } else {
      // 에러: 에러 콜백 호출
      req->cb(req, -errno);
      QUEUE_REMOVE(&req->queue);
    }
  }
}

---

8. 시스템 호출: write() syscall

최종적으로 write() 시스템 호출이 실행됩니다:

// 커널 레벨 (의사 코드)
ssize_t write(int fd, const void *buf, size_t count) {
  // 파일 디스크립터 확인
  struct file *f = get_file(fd);
  
  // 버퍼에서 커널 공간으로 복사
  copy_from_user(kernel_buf, buf, count);
  
  // 디바이스/파일에 쓰기
  return f->f_op->write(f, kernel_buf, count, &f->f_pos);
}

시스템 호출 단계:

1. 파일 디스크립터 확인: 유효한 파일 디스크립터인지 확인
2. 사용자 공간 → 커널 공간 복사: 데이터를 커널 공간으로 복사
3. 실제 I/O 수행: 디바이스 드라이버를 통해 실제 쓰기
4. 결과 반환: 쓰여진 바이트 수 또는 에러 코드 반환

---

9. 전체 실행 흐름 요약

이제 전체 흐름을 다시 정리해보겠습니다:

1. JavaScript: console.log('Hello World')
   ↓
2. lib/internal/console/constructor.js::log()
   - onLog.publish() (diagnostics_channel)
   - kFormatForStdout() 호출
   ↓
3. lib/internal/console/constructor.js::kFormatForStdout()
   - Fast path 체크 (단일 문자열이면 스킵)
   - formatWithOptions() 호출
   ↓
4. lib/internal/util/inspect.js::formatWithOptions()
   - formatWithOptionsInternal() 호출
   - inspect() 호출 (객체인 경우)
   ↓
5. lib/internal/console/constructor.js::kWriteToConsole()
   - 그룹 인덴트 처리
   - 개행 추가
   - 에러 핸들러 추가
   - stream.write() 호출
   ↓
6. lib/internal/streams/writable.js::write()
   - 버퍼에 추가
   - _write() 호출
   ↓
7. src/stream_base.cc::StreamBase::Write()
   - DoTryWrite() 시도 (동기 쓰기)
   - 실패 시 libuv로 전달
   ↓
8. libuv::uv_write()
   - 이벤트 루프에 등록
   ↓
9. 이벤트 루프 처리
   - write() syscall 실행
   ↓
10. 커널: write() syscall
    - 실제 I/O 수행

---

10. 성능에 영향을 주는 주요 요소

각 단계에서 발생하는 오버헤드를 정리하면:

10.1 포맷팅 오버헤드 (가장 큼)

• 객체 순회: 깊게 중첩된 객체를 재귀적으로 순회
• 문자열 생성: 많은 문자열 할당과 연결
• 순환 참조 감지: WeakSet을 사용한 순환 참조 추적
• 색상 코드: TTY인 경우 ANSI 코드 추가

10.2 I/O 오버헤드

• 동기 I/O (TTY): 이벤트 루프 블로킹 가능
• 비동기 I/O (파이프): 이벤트 루프를 통한 처리, 백프레셔 가능
• 시스템 호출: 커널 모드 전환 오버헤드

10.3 에러 핸들링 오버헤드

• 리스너 추가/제거: 매 호출마다 once('error', noop) 추가 및 제거
• try-catch: 동기 에러 처리

10.4 문자열 조작 오버헤드

• 인덴트 처리: 정규식 치환
• 개행 추가: 문자열 연결

---

결론

console.log는 단순해 보이지만 실제로는 여러 레이어를 거치는 복잡한 과정입니다:

1. JavaScript 레벨: 포맷팅과 스트림 쓰기 준비
2. Stream 레벨: 버퍼 관리와 백프레셔 처리
3. C++ 바인딩: JavaScript와 libuv 사이의 브릿지
4. libuv: 비동기 I/O와 이벤트 루프 통합
5. 시스템 호출: 실제 I/O 수행

각 단계에서 최적화가 이루어지고 있지만(예: Fast path, DoTryWrite), 여전히 많은 오버헤드가 발생합니다. 특히 포맷팅 단계에서 복잡한 객체를 처리할 때 가장 큰 부하가 발생합니다.

다음 글에서는 이러한 오버헤드를 실제로 측정하고, 최적화 방안을 제시하겠습니다.

참고 자료

• Node.js 소스 코드 - console/constructor.js
• Node.js 소스 코드 - util/inspect.js
• Node.js 소스 코드 - streams/writable.js
• Node.js 소스 코드 - stream_base.cc
• libuv 문서