[번역] Node.js 애플리케이션 프로파일링

원문: https://nodejs.org/en/learn/getting-started/profiling

Node.js 애플리케이션 프로파일링에는 애플리케이션이 실행되는 동안 CPU, 메모리 및 기타 런타임 메트릭을 분석하여 성능을 측정하는 작업이 포함됩니다. 이는 애플리케이션의 효율성, 응답성 및 확장성에 영향을 줄 수 있는 병목 현상, 높은 CPU 사용량, 메모리 누수 또는 느린 함수 호출을 식별하는 데 도움이 됩니다.

Node.js 애플리케이션을 프로파일링하는 데 사용할 수 있는 타사 도구가 많이 있지만 대부분의 경우 가장 쉬운 옵션은 Node.js 내장 프로파일러를 사용하는 것입니다. 내장 프로파일러는 프로그램 실행 중에 일정한 간격으로 스택을 샘플링하는 V8 내부의 프로파일러를 사용합니다. 이러한 샘플의 결과를 jit 컴파일과 같은 중요한 최적화 이벤트와 함께 일련의 틱으로 기록합니다.

code-creation,LazyCompile,0,0x2d5000a337a0,396,"bp native array.js:1153:16",0x289f644df68,~
code-creation,LazyCompile,0,0x2d5000a33940,716,"hasOwnProperty native v8natives.js:198:30",0x289f64438d0,~
code-creation,LazyCompile,0,0x2d5000a33c20,284,"ToName native runtime.js:549:16",0x289f643bb28,~
code-creation,Stub,2,0x2d5000a33d40,182,"DoubleToIStub"
code-creation,Stub,2,0x2d5000a33e00,507,"NumberToStringStub"

과거에는 틱을 해석하기 위해 V8 소스 코드가 필요했습니다. 다행히도 Node.js 4.4.0 버전부터 V8을 소스에서 별도로 빌드하지 않고도 이 정보를 쉽게 사용할 수 있는 도구가 도입되었습니다. 기본 제공 프로파일러가 애플리케이션 성능에 대한 통찰력을 제공하는 데 어떻게 도움이 되는지 살펴보겠습니다.

틱 프로파일러의 사용을 설명하기 위해 간단한 Express 애플리케이션을 사용하겠습니다. 우리 애플리케이션에는 두 개의 처리기가 있으며, 하나는 시스템에 새 사용자를 추가하기 위한 것입니다.

app.get('/newUser', (req, res) => {
  let username = req.query.username || '';
  const password = req.query.password || '';

  username = username.replace(/[^a-zA-Z0-9]/g, '');

  if (!username || !password || users[username]) {
    return res.sendStatus(400);
  }

  const salt = crypto.randomBytes(128).toString('base64');
  const hash = crypto.pbkdf2Sync(password, salt, 10000, 512, 'sha512');

  users[username] = { salt, hash };

  res.sendStatus(200);
});

사용자 인증 시도의 유효성을 검사하기 위한 다른 방법은 다음과 같습니다.

app.get('/auth', (req, res) => {
  let username = req.query.username || '';
  const password = req.query.password || '';

  username = username.replace(/[^a-zA-Z0-9]/g, '');

  if (!username || !password || !users[username]) {
    return res.sendStatus(400);
  }

  const { salt, hash } = users[username];
  const encryptHash = crypto.pbkdf2Sync(password, salt, 10000, 512, 'sha512');

  if (crypto.timingSafeEqual(hash, encryptHash)) {
    res.sendStatus(200);
  } else {
    res.sendStatus(401);
  }
});

이러한 핸들러는 Node.js 애플리케이션에서 사용자를 인증하는 데 권장되지 않으며 순전히 설명 목적으로 사용됩니다. 일반적으로 고유한 암호화 인증 메커니즘을 설계하려고 해서는 안 됩니다. 기존의 입증된 인증 솔루션을 사용하는 것이 훨씬 좋습니다.

이제 애플리케이션을 배포했고 사용자가 요청 지연 시간에 대해 불평한다고 가정합니다. 내장된 프로파일러를 사용하여 앱을 쉽게 실행할 수 있습니다.

NODE_ENV=production node --prof app.js

ab (ApacheBench)를 사용하여 서버에 약간의 부하를 가합니다.

curl -X GET "http://localhost:8080/newUser?username=matt&password=password"
ab -k -c 20 -n 250 "http://localhost:8080/auth?username=matt&password=password"

다음과 같은 ab 출력을 얻습니다.

Concurrency Level:      20
Time taken for tests:   46.932 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      50250 bytes
HTML transferred:       500 bytes
Requests per second:    5.33 [#/sec] (mean)
Time per request:       3754.556 [ms] (mean)
Time per request:       187.728 [ms] (mean, across all concurrent requests)
Transfer rate:          1.05 [Kbytes/sec] received
...
Percentage of the requests served within a certain time (ms)
  50%   3755
  66%   3804
  75%   3818
  80%   3825
  90%   3845
  95%   3858
  98%   3874
  99%   3875
 100%   4225 (longest request)

이 출력에서 초당 약 5개의 요청만 처리할 수 있으며 평균 요청은 왕복 4초 미만이 걸린다는 것을 알 수 있습니다. 실제 환경에서는 사용자 요청을 처리하기 위해 여러 함수에서 많은 작업을 수행합니다. 우리의 간단한 예제에서도 정규 표현식 컴파일, 임의 솔트 생성, 사용자 비밀번호로부터 고유한 해시 생성, 또는 Express 프레임워크 자체 내부 처리 등으로 시간이 손실될 수 있습니다.

--prof 옵션을 사용하여 애플리케이션을 실행했기 때문에 애플리케이션의 로컬 실행과 동일한 디렉토리에 틱 파일이 생성되었습니다. isolate-0xnnnnnnnnnnnn-v8.log 형식이어야 합니다(여기서 n은 숫자입니다).

이 파일을 이해하려면 Node.js 바이너리와 함께 번들로 제공되는 틱 프로세서를 사용해야 합니다. 프로세서를 실행하려면 --prof-process 플래그를 사용합니다.

node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

즐겨 사용하는 텍스트 편집기에서 processed.txt 파일을 열면 몇 가지 다른 유형의 정보가 제공됩니다. 파일은 여러 섹션으로 나뉘며, 이 섹션은 다시 언어별로 나뉩니다. 먼저 요약 섹션을 보고 다음을 확인합니다.

[Summary]:
   ticks  total  nonlib   name
     79    0.2%    0.2%  JavaScript
  36703   97.2%   99.2%  C++
      7    0.0%    0.0%  GC
    767    2.0%          Shared libraries
    215    0.6%          Unaccounted

이는 수집된 모든 샘플의 97%가 C++ 코드에서 발생했으며 처리된 출력의 다른 섹션을 볼 때 자바스크립트가 아닌 C++로 수행되는 작업에 가장 주의를 기울여야 함을 나타냅니다. 이를 염두에 두고 다음으로 CPU 시간을 가장 많이 소비하는 C++ 함수에 대한 정보가 포함된 [C++] 섹션을 찾아 다음을 확인합니다.

[C++]:
   ticks  total  nonlib   name
  19557   51.8%   52.9%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
   4510   11.9%   12.2%  _sha1_block_data_order
   3165    8.4%    8.6%  _malloc_zone_malloc

위 출력에서 상위 3개 항목이 프로그램에서 사용하는 CPU 시간의 72.1%를 차지하는 것을 볼 수 있습니다. 이 출력에서 CPU 시간의 최소 51.8%가 사용자 암호에서 해시 생성에 해당하는 PBKDF2라는 함수가 차지한다는 것을 즉시 알 수 있습니다. 그러나 아래쪽 두 항목이 애플리케이션에 미치는 영향을 바로 파악하기는 어려울 수 있습니다(또는 예시를 위해 그렇지 않은 척 하겠습니다). 이러한 함수 간의 관계를 더 잘 이해하기 위해 다음으로 각 함수의 기본 호출자에 대한 정보를 제공하는 [상향식(무거운) 프로필] 섹션을 살펴보겠습니다. 이 섹션을 살펴보면 다음과 같은 결과를 얻을 수 있습니다.

  ticks parent  name
  19557   51.8%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
  19557  100.0%    v8::internal::Builtins::~Builtins()
  19557  100.0%      LazyCompile: ~pbkdf2 crypto.js:557:16
   4510   11.9%  _sha1_block_data_order
   4510  100.0%    LazyCompile: *pbkdf2 crypto.js:557:16
   4510  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30
   3165    8.4%  _malloc_zone_malloc
   3161   99.9%    LazyCompile: *pbkdf2 crypto.js:557:16
   3161  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30

이 섹션을 구문 분석하려면 위의 원시 틱 수보다 약간 더 많은 작업이 필요합니다. 위의 각 "호출 스택" 내에서 부모 열의 백분율은 위 행의 함수가 현재 행의 함수에 의해 호출된 샘플의 백분율을 알려줍니다. 예를 들어, _sha1_block_data_order에 대한 위의 중간 "호출 스택"에서 _sha1_block_data_order이 샘플의 11.9%에서 발생했음을 알 수 있으며, 이는 위의 원시 카운트에서 알 수 있습니다. 그러나 여기에서 Node.js crypto 모듈 내부의 pbkdf2 함수에 의해 항상 호출되었음을 알 수 있습니다. 마찬가지로 _malloc_zone_malloc도 거의 독점적으로 동일한 pbkdf2 함수에 의해 호출되었음을 알 수 있습니다. 따라서 이 뷰의 정보를 활용하면, 사용자 비밀번호로부터의 해시 계산이 위에서 언급한 51.8%뿐만 아니라 상위 3개 가장 많이 샘플링된 함수의 모든 CPU 시간을 차지한다는 것을 알 수 있습니다. 왜냐하면 _sha1_block_data_order와 _malloc_zone_malloc에 대한 호출이 pbkdf2 함수를 대신하여 이루어졌기 때문입니다.

이 시점에서 패스워드 기반 해시 생성이 우리의 최적화 목표가 되어야 한다는 것이 매우 명확합니다. 다행히도 당신은 비동기 프로그래밍의 이점을 완전히 체득했고, 그리고 사용자의 암호에서 사용자의 패스워드로부터 해시를 생성하는 작업이 동기적인 방식으로 수행되고 있어서 이벤트 루프를 묶어두고 있다는 것을 깨달았습니다. 이는 해시를 계산하는 동안 다른 들어오는 요청들을 처리하는 것을 방해합니다.

이 문제를 해결하려면 위의 핸들러를 약간 수정하여 pbkdf2 함수의 비동기 버전을 사용합니다.

app.get('/auth', (req, res) => {
  let username = req.query.username || '';
  const password = req.query.password || '';

  username = username.replace(/[^a-zA-Z0-9]/g, '');

  if (!username || !password || !users[username]) {
    return res.sendStatus(400);
  }

  crypto.pbkdf2(
    password,
    users[username].salt,
    10000,
    512,
    'sha512',
    (err, hash) => {
      if (users[username].hash.toString() === hash.toString()) {
        res.sendStatus(200);
      } else {
        res.sendStatus(401);
      }
    }
  );
});

위의 ab 벤치 마크를 비동기 버전의 앱으로 새로 실행하면 다음과 같은 결과가 생성됩니다.

Concurrency Level:      20
Time taken for tests:   12.846 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      50250 bytes
HTML transferred:       500 bytes
Requests per second:    19.46 [#/sec] (mean)
Time per request:       1027.689 [ms] (mean)
Time per request:       51.384 [ms] (mean, across all concurrent requests)
Transfer rate:          3.82 [Kbytes/sec] received
...
Percentage of the requests served within a certain time (ms)
  50%   1018
  66%   1035
  75%   1041
  80%   1043
  90%   1049
  95%   1063
  98%   1070
  99%   1071
 100%   1079 (longest request)

야호! 이제 앱은 초당 약 20개의 요청을 처리하고 있으며, 이는 동기 해시 생성보다 약 4배 더 많습니다. 또한 평균 대기 시간이 이전 4초에서 1초 남짓으로 감소했습니다.

이 (인위적임이 인정되는) 예제의 성능 조사를 통해 V8 틱 프로세서가 Node.js 애플리케이션의 성능을 더 잘 이해하는 데 어떻게 도움이 되는지 확인했기를 바랍니다.

플레임 그래프를 만드는 방법도 도움이 될 수 있습니다.

🚀 한국어로 된 프런트엔드 아티클을 빠르게 받아보고 싶다면 Korean FE Article을 구독해주세요!