Node.js 애플리케이션 프로파일링
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(/[!@#$%^&*]/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(/[!@#$%^&*]/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++ 코드에서 발생했으며 처리된 출력의 다른 섹션을 볼 때 JavaScript가 아닌 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라는 함수에 의해 소요된다는 것을 즉시 알 수 있습니다. 그러나 하위 두 항목이 우리 애플리케이션에 어떻게 영향을 미치는지 (또는 그렇다고 가정하면 예시를 위해 다른 것처럼 가장할 것입니다.) 즉시 명확하지 않을 수 있습니다. 이러한 함수 간의 관계를 더 잘 이해하기 위해 각 함수의 기본 호출자에 대한 정보를 제공하는 [Bottom up (heavy) profile] 섹션을 살펴보겠습니다. 이 섹션을 검사하면 다음과 같은 내용이 있습니다.
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 암호화 모듈 내부의 pbkdf2 함수에 의해 항상 호출되었다는 것을 알 수 있습니다. 마찬가지로 _malloc_zone_malloc는 거의 전적으로 동일한 pbkdf2 함수에 의해 호출되었습니다. 따라서 이 보기의 정보를 사용하여 사용자 비밀번호에서 해시를 계산하는 데는 위에서 51.8%일 뿐만 아니라 _sha1_block_data_order 및 _malloc_zone_malloc 호출이 pbkdf2 함수를 대신하여 이루어졌기 때문에 가장 많이 샘플링된 상위 3개 함수의 모든 CPU 시간이 필요하다는 것을 알 수 있습니다.
이 시점에서 비밀번호 기반 해시 생성이 최적화의 대상이 되어야 한다는 것이 매우 분명합니다. 다행히도 비동기 프로그래밍의 이점을 완전히 내면화하고 사용자 비밀번호에서 해시를 생성하는 작업이 동기식으로 수행되어 이벤트 루프를 연결한다는 것을 깨닫습니다. 이렇게 하면 해시를 계산하는 동안 다른 들어오는 요청에서 작업하는 것을 방해합니다.
이 문제를 해결하기 위해 pbkdf2 함수의 비동기 버전을 사용하도록 위의 핸들러를 약간 수정합니다.
app.get('/auth', (req, res) => {
let username = req.query.username || ''
const password = req.query.password || ''
username = username.replace(/[!@#$%^&*]/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 애플리케이션의 성능을 더 잘 이해하는 데 어떻게 도움이 되는지 알 수 있기를 바랍니다.
플레임 그래프 생성 방법도 도움이 될 수 있습니다.