Pino는 어떻게 구현되어 있을까? 내부 코드와 실제 벤치마크 분석

서론

이전 글에서 console.log의 내부 동작을 분석하고, 성능 최적화 방안을 살펴봤습니다.

---

프로젝트에서 로깅을 구현할 때 Pino를 자주 사용해왔습니다. 구조화된 JSON 로깅과 간편한 사용법이 매력적이었지만, 실제로 어떤 이점이 있는지, 성능상 어떤 점에서 이점이 있었을지 궁금해졌습니다. 단순히 마케팅 문구일 수도 있고, 실제로 내부 구현에서 차별화된 최적화가 있을 수도 있으니까요.

이런 궁금증에서 시작해서, 이번 글에서는 실제로 프로덕션에서 사용되는 로깅 라이브러리인 Pino가 어떻게 구현되어 있는지, 실제 소스 코드와 벤치마크 결과를 통해 분석해보겠습니다.

Pino는 "super fast, all natural json logger"를 표방하며, 매우 낮은 오버헤드로 로깅을 수행합니다. 흥미롭게도, 실제 벤치마크 결과는 예상과 다소 달랐습니다:

• 출력 억제 상태 (I/O 없음): console.log가 더 빠름
• 실제 I/O 포함: Pino가 더 빠름

이 글에서는 Pino의 내부 구현을 분석하고, 실제 벤치마크 결과를 통해 언제, 왜 Pino가 유리한지, 그리고 프로젝트에서 사용했을 때 어떤 이점이 있었는지 알아보겠습니다.

---

1. Pino의 핵심 설계 원칙

Pino가 빠른 이유는 다음과 같은 설계 원칙 때문입니다:

1. JSON 직렬화 최적화: 객체를 JSON 문자열로 변환하는 과정을 최적화
2. 비동기 로깅: 메인 스레드를 블로킹하지 않는 비동기 쓰기
3. SonicBoom: 고속 파일/스트림 쓰기를 위한 전용 모듈
4. 최소한의 오버헤드: 불필요한 검증과 변환 최소화
5. 워커 스레드 기반 Transport: 로그 처리와 포맷팅을 별도 스레드에서 수행

---

2. 기본 사용법과 내부 동작

2.1 기본 사용법

const pino = require('pino');
const logger = pino();

logger.info('hello world');
logger.info({ userId: 123 }, 'User logged in');

이 코드는 다음과 같은 JSON 로그를 출력합니다:

{"level":30,"time":1531171074631,"msg":"hello world","pid":657,"hostname":"Davids-MBP-3.fritz.box"}
{"level":30,"time":1531171082399,"msg":"User logged in","pid":657,"hostname":"Davids-MBP-3.fritz.box","userId":123}

2.2 Pino 인스턴스 생성

Pino의 메인 파일인 pino.js를 살펴보면:

// pino.js (의사 코드)
function pino(opts = {}, stream) {
  // 기본 옵션 설정
  const {
    level = 'info',
    serializers = {},
    // ... 기타 옵션
  } = opts;

  // 스트림 설정 (기본값: process.stdout)
  stream = stream || pino.destination();

  // 로거 인스턴스 생성
  return new Pino({ level, serializers, stream });
}

주요 특징:

• 기본 출력은 process.stdout (파이프 가능)
• 옵션 기반 설정으로 유연성 제공
• 스트림 기반 아키텍처로 다양한 출력 대상 지원

---

3. JSON 직렬화 최적화

3.1 console.log vs Pino의 차이

console.log의 문제점:

• inspect() 함수를 사용하여 객체를 문자열로 변환
• 재귀적 순회, 순환 참조 감지, 색상 코드 추가 등 많은 오버헤드
• 읽기 쉬운 형식이지만 파싱이 어려움

Pino의 접근:

• JSON.stringify()를 직접 사용
• JSON은 파싱이 빠르고 구조화되어 있음
• 추가 포맷팅 없이 최소한의 변환만 수행

3.2 JSON 직렬화 구현

Pino는 내부적으로 다음과 같이 JSON 직렬화를 수행합니다:

// lib/proto.js (의사 코드)
Pino.prototype.asJson = function (obj, msg, num) {
  // 타임스탬프, 레벨, 메시지 등 기본 필드 구성
  const logObj = {
    level: num,
    time: Date.now(),
    msg: msg,
    pid: process.pid,
    hostname: this.hostname
  };

  // 사용자 객체 병합
  if (obj && typeof obj === 'object') {
    Object.assign(logObj, obj);
  }

  // JSON 직렬화
  return JSON.stringify(logObj) + '\n';
};

최적화 포인트:

1. 단순한 객체 병합: Object.assign() 사용으로 빠른 병합
2. 직접 JSON.stringify(): inspect() 대신 네이티브 JSON 직렬화 사용
3. 최소한의 필드: 필요한 필드만 추가하여 오버헤드 최소화

3.3 Fast-JSON-Stringify (선택적)

Pino는 선택적으로 fast-json-stringify를 사용할 수 있습니다:

// fast-json-stringify를 사용한 경우
const fastJson = require('fast-json-stringify');
const stringify = fastJson({
  type: 'object',
  properties: {
    level: { type: 'integer' },
    time: { type: 'integer' },
    msg: { type: 'string' },
    // ... 스키마 정의
  }
});

// 스키마 기반 직렬화로 더 빠른 성능
const json = stringify(logObj);

장점:

• 스키마 기반으로 최적화된 직렬화
• 런타임 검증 최소화
• 일반 JSON.stringify()보다 2-3배 빠름

---

4. 비동기 로깅: SonicBoom

Pino의 성능 핵심은 SonicBoom입니다. SonicBoom은 고속 파일/스트림 쓰기를 위한 전용 모듈입니다.

4.1 SonicBoom의 역할

SonicBoom은 다음과 같은 최적화를 제공합니다:

1. 버퍼링: 여러 로그를 모아서 한 번에 쓰기
2. 비동기 쓰기: 메인 스레드 블로킹 방지
3. 최적화된 파일 I/O: 직접 파일 디스크립터 사용

4.2 SonicBoom 사용 예시

// pino.destination()은 내부적으로 SonicBoom을 사용
const pino = require('pino');
const logger = pino(pino.destination('./app.log'));

// 또는 직접 사용
const SonicBoom = require('sonic-boom');
const stream = new SonicBoom({ fd: process.stdout.fd });
const logger = pino(stream);

4.3 SonicBoom 내부 동작 (의사 코드)

// sonic-boom/index.js (의사 코드)
class SonicBoom {
  constructor(opts) {
    this.fd = opts.fd || fs.openSync(opts.dest, 'a');
    this.buffer = Buffer.allocUnsafe(65536); // 64KB 버퍼
    this.bufLength = 0;
    this.minLength = opts.minLength || 0;
    this.maxLength = opts.maxLength || 0;
    this.sync = opts.sync || false;
  }

  write(data) {
    const dataLength = Buffer.byteLength(data);
    
    // 버퍼에 추가
    if (this.bufLength + dataLength < this.buffer.length) {
      this.buffer.write(data, this.bufLength);
      this.bufLength += dataLength;
      
      // 최소 길이에 도달하면 플러시
      if (this.bufLength >= this.minLength) {
        this.flush();
      }
    } else {
      // 버퍼가 가득 차면 먼저 플러시
      this.flush();
      this.write(data);
    }
  }

  flush() {
    if (this.bufLength > 0) {
      // 비동기 쓰기
      fs.write(this.fd, this.buffer.slice(0, this.bufLength), () => {});
      this.bufLength = 0;
    }
  }
}

주요 최적화:

1. 큰 버퍼 사용: 64KB 버퍼로 작은 쓰기 작업 감소
2. 배치 쓰기: 여러 로그를 모아서 한 번에 쓰기
3. 비동기 I/O: fs.write()를 사용하여 메인 스레드 블로킹 방지
4. 직접 파일 디스크립터: 스트림 래퍼 없이 직접 파일에 쓰기

---

5. 로그 레벨 필터링

Pino는 로그 레벨에 따른 필터링을 매우 효율적으로 수행합니다:

// lib/levels.js (의사 코드)
const levels = {
  trace: 10,
  debug: 20,
  info: 30,
  warn: 40,
  error: 50,
  fatal: 60
};

Pino.prototype.info = function (obj, msg) {
  // 레벨 체크 - 매우 빠른 정수 비교
  if (this.level > 30) {
    return; // 로깅 스킵
  }
  
  // 실제 로깅 수행
  this.write(obj, msg, 30);
};

최적화 포인트:

• 정수 비교: 문자열 비교 대신 정수 비교로 매우 빠름
• 조기 반환: 레벨이 맞지 않으면 즉시 반환하여 오버헤드 제로
• 인라인 최적화: V8 엔진이 인라인 최적화 가능

---

6. Child Logger 최적화

Pino의 Child Logger는 매우 효율적으로 구현되어 있습니다:

// lib/child.js (의사 코드)
Pino.prototype.child = function (bindings) {
  const child = Object.create(this);
  child.bindings = Object.assign({}, this.bindings, bindings);
  return child;
};

// 사용 예시
const logger = pino();
const childLogger = logger.child({ userId: 123 });

childLogger.info('Action performed');
// 출력: {"level":30,"time":...,"msg":"Action performed","userId":123}

최적화 포인트:

1. 프로토타입 상속: Object.create()로 메모리 효율적
2. 바인딩 병합: 로그 작성 시에만 병합하여 오버헤드 최소화
3. 불변성: 원본 로거를 변경하지 않음

---

7. 실제 성능 비교

실제로 Node.js 환경에서 console.log와 Pino의 성능을 측정해보았습니다. 결과는 예상과 다소 달랐습니다.

7.1 테스트 환경

테스트는 두 가지 시나리오로 나누어 수행했습니다:

1. 출력 억제 상태 (I/O 없음): 순수한 포맷팅과 직렬화 성능 측정
2. 실제 I/O 포함: 실제 파일/스트림 쓰기를 포함한 종합 성능 측정

테스트 코드는 console-log-investigation 디렉토리에 있으며, 다음과 같이 실행할 수 있습니다:

cd console-log-investigation
npm install pino
node pino-benchmark.js > /dev/null 2>&1
node pino-test-with-io.js > /dev/null 2>&1

7.2 출력 억제 상태 테스트 결과

I/O를 완전히 억제한 상태에서 순수한 포맷팅 성능을 측정한 결과:

놀라운 발견:

• 출력 억제 상태에서는 console.log가 Pino보다 약 10-15배 빠릅니다!
• console.log의 fast path 최적화가 매우 효율적입니다
• Pino는 JSON 직렬화와 객체 생성 오버헤드가 있습니다

왜 console.log가 더 빠른가?

1. Fast path 최적화: console.log는 단순 문자열의 경우 거의 오버헤드 없이 처리
2. 최소한의 변환: 객체의 경우에도 inspect()를 사용하지만, 출력 억제 상태에서는 실제 I/O가 없어 빠름
3. Pino의 오버헤드: JSON 직렬화, 객체 병합, 메타데이터 추가 등의 비용

7.3 실제 I/O 포함 테스트 결과

실제로 출력을 포함한 테스트 결과 (1,000회 반복):

실제 I/O에서는 Pino가 더 빠릅니다:

• Pino가 console.log보다 약 2.2% 빠름 (1.02배)
• 메모리 사용량도 더 효율적 (음수는 가비지 컬렉션으로 인한 메모리 회수)

왜 실제 I/O에서는 Pino가 더 빠른가?

1. SonicBoom의 버퍼링: 여러 로그를 모아서 배치 쓰기로 시스템 호출 감소
2. 비동기 I/O 최적화: 메인 스레드 블로킹 최소화
3. 직접 파일 디스크립터 사용: 스트림 래퍼 없이 직접 파일에 쓰기
4. JSON 직렬화의 효율성: 구조화된 JSON은 파싱과 처리가 빠름

7.4 성능 비교 분석

이 결과는 중요한 인사이트를 제공합니다:

1. 개발/디버깅 환경:

• 출력 억제 상태에서는 console.log가 더 빠름
• 하지만 실제로는 I/O가 포함되므로 차이가 크지 않음
• 개발 환경에서는 편의성이 더 중요할 수 있음

2. 프로덕션 환경:

• 실제 I/O가 포함되면 Pino가 더 빠름
• 메모리 사용량도 더 효율적
• 구조화된 JSON 로그는 파싱과 분석이 쉬움

3. 성능 최적화의 핵심:

• Pino의 장점은 I/O 효율성에 있습니다
• 순수 포맷팅만 보면 console.log가 빠르지만, 실제 프로덕션에서는 I/O가 병목
• SonicBoom의 버퍼링과 비동기 쓰기가 핵심

7.5 실제 벤치마크 코드

테스트에 사용된 코드는 다음과 같습니다:

// pino-benchmark.js - 출력 억제 상태 테스트
const { performance } = require('perf_hooks');
const pino = require('pino');
const logger = pino({ level: 'info' });

function benchmark(name, fn, iterations = 10000) {
  // 출력 완전 억제
  const originalStdout = process.stdout.write;
  const originalStderr = process.stderr.write;
  const originalLog = console.log;
  const originalError = console.error;
  
  process.stdout.write = () => true;
  process.stderr.write = () => true;
  console.log = () => {};
  console.error = () => {};
  
  const startMem = process.memoryUsage();
  const startTime = performance.now();
  
  for (let i = 0; i < iterations; i++) {
    fn(i);
  }
  
  const endTime = performance.now();
  const endMem = process.memoryUsage();
  
  // 출력 복원
  process.stdout.write = originalStdout;
  process.stderr.write = originalStderr;
  console.log = originalLog;
  console.error = originalError;
  
  return {
    name,
    duration: endTime - startTime,
    opsPerSec: (iterations / (endTime - startTime) * 1000).toFixed(0),
    memoryDelta: {
      heapUsed: endMem.heapUsed - startMem.heapUsed
    }
  };
}

// 테스트 실행
const results = [];
results.push(benchmark('console.log (object)', (i) => {
  console.log({ userId: i, action: 'test' }, 'User action');
}, 10000));

results.push(benchmark('Pino (object)', (i) => {
  logger.info({ userId: i, action: 'test' }, 'User action');
}, 10000));

// pino-test-with-io.js - 실제 I/O 포함 테스트
async function benchmarkWithIO(name, fn, iterations = 1000) {
  const startTime = performance.now();
  const startMem = process.memoryUsage();
  
  for (let i = 0; i < iterations; i++) {
    fn(i);
  }
  
  // Pino flush 대기
  if (logger.flushSync) {
    logger.flushSync();
  }
  
  const endTime = performance.now();
  const endMem = process.memoryUsage();
  
  return {
    name,
    duration: endTime - startTime,
    opsPerSec: (iterations / (endTime - startTime) * 1000).toFixed(0),
    memoryDelta: {
      heapUsed: endMem.heapUsed - startMem.heapUsed
    }
  };
}

참고: 전체 테스트 코드와 결과는 console-log-investigation/benchmark-results.txt 파일에서 확인할 수 있습니다.

---

8. Transport: 워커 스레드 기반 로그 처리

Pino는 로그 포맷팅과 처리를 별도 워커 스레드에서 수행할 수 있습니다:

8.1 Transport 사용

const pino = require('pino');

const logger = pino({
  transport: {
    target: 'pino-pretty', // 개발 환경용 포맷터
    options: {
      colorize: true
    }
  }
});

// 또는 파일로 저장
const logger = pino({
  transport: {
    target: 'pino/file',
    options: {
      destination: './app.log'
    }
  }
});

8.2 Transport의 장점

1. 메인 스레드 분리: 로그 포맷팅이 메인 스레드를 블로킹하지 않음
2. 병렬 처리: 여러 Transport를 동시에 사용 가능
3. 에러 격리: Transport 에러가 애플리케이션에 영향 없음

8.3 Transport 내부 동작

// pino.transport() (의사 코드)
function transport(opts) {
  const { Worker } = require('worker_threads');
  
  const worker = new Worker(opts.target, {
    workerData: opts.options
  });
  
  // 메인 스레드에서 로그를 워커로 전송
  return {
    write(chunk) {
      worker.postMessage(chunk);
    }
  };
}

---

9. 주요 최적화 기법 요약

9.1 JSON 직렬화 최적화

• JSON.stringify() 직접 사용 (inspect() 대신)
• 최소한의 필드만 직렬화
• 선택적 fast-json-stringify 사용

9.2 비동기 I/O 최적화

• SonicBoom을 통한 버퍼링
• 배치 쓰기로 시스템 호출 감소
• 직접 파일 디스크립터 사용

9.3 레벨 필터링 최적화

• 정수 기반 레벨 비교
• 조기 반환으로 불필요한 작업 스킵
• V8 인라인 최적화 활용

9.4 메모리 최적화

• 프로토타입 상속으로 메모리 효율
• 버퍼 재사용
• 불필요한 객체 생성 최소화

---

10. console.log와의 차이점 정리

---

11. 실제 사용 시나리오

11.1 개발 환경

const pino = require('pino');

const logger = pino({
  level: 'debug',
  transport: {
    target: 'pino-pretty',
    options: {
      colorize: true,
      translateTime: 'SYS:standard'
    }
  }
});

11.2 프로덕션 환경

const pino = require('pino');

const logger = pino({
  level: 'info',
  // 파일로 직접 출력 (SonicBoom 사용)
  destination: pino.destination('./logs/app.log')
});

// 또는 stdout으로 출력하고 외부에서 리다이렉트
const logger = pino({
  level: 'info'
});
// $ node app.js > app.log

11.3 구조화된 로깅

const logger = pino();

// 컨텍스트와 함께 로깅
logger.info({ 
  userId: 123, 
  action: 'login',
  ip: '192.168.1.1'
}, 'User logged in');

// Child logger로 컨텍스트 유지
const requestLogger = logger.child({ requestId: 'req-123' });
requestLogger.info('Processing request');
requestLogger.info('Request completed');

---

결론

실제 벤치마크 결과를 통해 확인한 Pino의 장점은 다음과 같습니다:

핵심 발견

1. 출력 억제 상태 (I/O 없음): console.log가 더 빠름

   • console.log: ~14,741,109 ops/sec
   • Pino: ~1,266,671 ops/sec
   • console.log의 fast path 최적화가 매우 효율적

2. 실제 I/O 포함: Pino가 더 빠름

   • console.log: ~9,442 ops/sec
   • Pino: ~9,656 ops/sec (약 2.2% 빠름)
   • 메모리 사용량도 더 효율적

Pino가 실제 프로덕션에서 유리한 이유

1. SonicBoom의 버퍼링: 실제 I/O에서 배치 쓰기의 효율성
2. 비동기 I/O 최적화: 메인 스레드 블로킹 최소화
3. 구조화된 JSON: 파싱과 분석이 쉬움
4. 메모리 효율성: 더 적은 메모리 사용
5. 확장성: Transport를 통한 워커 스레드 활용

실무 적용 가이드

• 개발 환경: console.log도 충분히 빠르고 편리함
• 프로덕션 환경: Pino의 I/O 효율성과 구조화된 로깅이 유리
• 고부하 시스템: Pino의 비동기 버퍼링과 Transport 활용 필수

프로덕션 환경에서는 실제 I/O가 포함되므로, Pino와 같은 전문 로깅 라이브러리를 사용하는 것이 성능과 유지보수성 측면에서 훨씬 유리합니다. 특히 고부하 시스템에서는 SonicBoom의 버퍼링과 비동기 쓰기가 핵심적인 성능 향상을 제공합니다.

---

참고 자료

• Pino GitHub 저장소
• Pino 공식 문서
• Pino 벤치마크
• SonicBoom GitHub 저장소
• fast-json-stringify