Profiling von Node.js-Anwendungen
Es gibt viele Drittanbieter-Tools für das Profiling von Node.js-Anwendungen, aber in vielen Fällen ist die einfachste Option die Verwendung des in Node.js integrierten Profilers. Der integrierte Profiler verwendet den Profiler in V8, der den Stack in regelmäßigen Abständen während der Programmausführung abtastet. Er zeichnet die Ergebnisse dieser Abtastungen zusammen mit wichtigen Optimierungsereignissen wie JIT-Kompilierungen als eine Reihe von Ticks auf:
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"In der Vergangenheit benötigten Sie den V8-Quellcode, um die Ticks interpretieren zu können. Glücklicherweise wurden seit Node.js 4.4.0 Tools eingeführt, die die Nutzung dieser Informationen erleichtern, ohne dass V8 separat aus dem Quellcode erstellt werden muss. Sehen wir uns an, wie der integrierte Profiler Einblicke in die Anwendungsleistung liefern kann.
Um die Verwendung des Tick-Profilers zu veranschaulichen, werden wir mit einer einfachen Express-Anwendung arbeiten. Unsere Anwendung wird zwei Handler haben, einen zum Hinzufügen neuer Benutzer zu unserem System:
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)
})und einen weiteren zur Validierung von Benutzerauthentifizierungsversuchen:
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)
}
})Bitte beachten Sie, dass dies KEINE empfohlenen Handler für die Authentifizierung von Benutzern in Ihren Node.js-Anwendungen sind und nur zu Illustrationszwecken verwendet werden. Sie sollten im Allgemeinen nicht versuchen, Ihre eigenen kryptografischen Authentifizierungsmechanismen zu entwerfen. Es ist viel besser, bestehende, bewährte Authentifizierungslösungen zu verwenden.
Nehmen wir nun an, dass wir unsere Anwendung bereitgestellt haben und sich Benutzer über hohe Latenzzeiten bei Anfragen beschweren. Wir können die App einfach mit dem integrierten Profiler ausführen:
NODE_ENV=production node --prof app.jsund mit ab (ApacheBench) etwas Last auf den Server legen:
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"und erhalten eine ab-Ausgabe von:
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)Aus dieser Ausgabe sehen wir, dass wir nur etwa 5 Anfragen pro Sekunde bearbeiten können und dass die durchschnittliche Anfrage etwas weniger als 4 Sekunden für die Hin- und Rückreise benötigt. In einem realen Beispiel könnten wir viele Aufgaben in vielen Funktionen im Auftrag einer Benutzeranfrage erledigen, aber selbst in unserem einfachen Beispiel könnte Zeit durch das Kompilieren regulärer Ausdrücke, das Generieren zufälliger Salts, das Generieren eindeutiger Hashes aus Benutzerpasswörtern oder innerhalb des Express-Frameworks selbst verloren gehen.
Da wir unsere Anwendung mit der Option --prof ausgeführt haben, wurde eine Tick-Datei im selben Verzeichnis wie Ihre lokale Ausführung der Anwendung generiert. Sie sollte die Form isolate-0xnnnnnnnnnnnn-v8.log haben (wobei n eine Ziffer ist).
Um diese Datei zu interpretieren, müssen wir den Tick-Prozessor verwenden, der mit der Node.js-Binärdatei gebündelt ist. Um den Prozessor auszuführen, verwenden Sie das Flag --prof-process:
node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txtDas Öffnen von processed.txt in Ihrem bevorzugten Texteditor liefert Ihnen einige verschiedene Arten von Informationen. Die Datei ist in Abschnitte unterteilt, die wiederum nach Sprache unterteilt sind. Zuerst betrachten wir den Zusammenfassungsabschnitt und sehen:
[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% UnaccountedDies zeigt uns, dass 97 % aller gesammelten Samples in C++-Code aufgetreten sind und dass wir beim Betrachten anderer Abschnitte der verarbeiteten Ausgabe der Arbeit in C++ (im Gegensatz zu JavaScript) die größte Aufmerksamkeit schenken sollten. In diesem Sinne finden wir als Nächstes den Abschnitt [C++], der Informationen darüber enthält, welche C++-Funktionen die meiste CPU-Zeit beanspruchen, und sehen:
[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_mallocWir sehen, dass die Top-3-Einträge 72,1 % der vom Programm benötigten CPU-Zeit ausmachen. Aus dieser Ausgabe sehen wir sofort, dass mindestens 51,8 % der CPU-Zeit von einer Funktion namens PBKDF2 beansprucht werden, was unserer Hash-Generierung aus dem Passwort eines Benutzers entspricht. Es ist jedoch möglicherweise nicht sofort ersichtlich, wie sich die unteren beiden Einträge in unserer Anwendung auswirken (oder wenn es so ist, werden wir es aus Gründen des Beispiels anders darstellen). Um die Beziehung zwischen diesen Funktionen besser zu verstehen, betrachten wir als Nächstes den Abschnitt [Bottom up (heavy) profile], der Informationen über die primären Aufrufer jeder Funktion liefert. Wenn wir diesen Abschnitt untersuchen, finden wir:
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:30Das Parsen dieses Abschnitts erfordert etwas mehr Arbeit als die rohen Tick-Zahlen oben. Innerhalb jedes der obigen "Call Stacks" gibt der Prozentsatz in der Spalte parent den Prozentsatz der Samples an, für die die Funktion in der Zeile oben von der Funktion in der aktuellen Zeile aufgerufen wurde. In der mittleren "Call Stack" oben für _sha1_block_data_order sehen wir beispielsweise, dass _sha1_block_data_order in 11,9 % der Samples vorkam, was wir aus den rohen Zählungen oben wussten. Hier können wir jedoch auch erkennen, dass es immer von der pbkdf2-Funktion innerhalb des Node.js-Kryptomoduls aufgerufen wurde. Wir sehen, dass _malloc_zone_malloc ebenfalls fast ausschließlich von derselben pbkdf2-Funktion aufgerufen wurde. Daher können wir mit den Informationen in dieser Ansicht erkennen, dass unsere Hash-Berechnung aus dem Benutzerpasswort nicht nur für die 51,8 % von oben, sondern auch für die gesamte CPU-Zeit in den Top 3 der am häufigsten gesampelten Funktionen verantwortlich ist, da die Aufrufe von _sha1_block_data_order und _malloc_zone_malloc im Namen der pbkdf2-Funktion erfolgten.
An diesem Punkt ist sehr klar, dass die passwortbasierte Hash-Generierung das Ziel unserer Optimierung sein sollte. Glücklicherweise haben Sie die Vorteile der asynchronen Programmierung vollständig verinnerlicht und erkennen, dass die Arbeit zum Generieren eines Hash aus dem Passwort des Benutzers synchron erfolgt und somit die Event-Schleife blockiert. Dies hindert uns daran, an anderen eingehenden Anfragen zu arbeiten, während wir einen Hash berechnen.
Um dieses Problem zu beheben, nehmen Sie eine kleine Änderung an den obigen Handlern vor, um die asynchrone Version der pbkdf2-Funktion zu verwenden:
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)
}
})
})Eine neue Ausführung des obigen ab-Benchmarks mit der asynchronen Version Ihrer App ergibt:
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)Yay! Ihre App bearbeitet jetzt etwa 20 Anfragen pro Sekunde, also etwa 4-mal mehr als mit der synchronen Hash-Generierung. Außerdem ist die durchschnittliche Latenz von den vorherigen 4 Sekunden auf etwas mehr als 1 Sekunde gesunken.
Hoffentlich haben Sie durch die Leistungsuntersuchung dieses (zugegebenermaßen konstruierten) Beispiels gesehen, wie der V8-Tick-Prozessor Ihnen helfen kann, ein besseres Verständnis für die Leistung Ihrer Node.js-Anwendungen zu gewinnen.
Möglicherweise finden Sie auch wie man eine Flame Graph erstellt hilfreich.