Profilatura delle Applicazioni Node.js
Esistono molti strumenti di terze parti disponibili per la profilatura delle applicazioni Node.js, ma in molti casi l'opzione più semplice è utilizzare il profiler integrato di Node.js. Il profiler integrato utilizza il profiler interno di V8 che campionaa lo stack a intervalli regolari durante l'esecuzione del programma. Registra i risultati di questi campioni, insieme a importanti eventi di ottimizzazione come le compilazioni jit, come una serie di tick:
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 passato, era necessario il codice sorgente di V8 per poter interpretare i tick. Fortunatamente, da Node.js 4.4.0 sono stati introdotti strumenti che facilitano il consumo di queste informazioni senza dover compilare separatamente V8 dal sorgente. Vediamo come il profiler integrato può aiutare a fornire informazioni sulle prestazioni dell'applicazione.
Per illustrare l'utilizzo del profiler tick, lavoreremo con una semplice applicazione Express. La nostra applicazione avrà due handler, uno per aggiungere nuovi utenti al nostro sistema:
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)
})e un altro per la convalida dei tentativi di autenticazione utente:
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)
}
})Si prega di notare che questi NON sono handler consigliati per l'autenticazione degli utenti nelle vostre applicazioni Node.js e sono utilizzati puramente a scopo illustrativo. In generale, non si dovrebbe cercare di progettare i propri meccanismi di autenticazione crittografica. È molto meglio utilizzare soluzioni di autenticazione esistenti e collaudate.
Ora supponiamo di aver distribuito la nostra applicazione e che gli utenti si lamentino dell'elevata latenza delle richieste. Possiamo facilmente eseguire l'applicazione con il profiler integrato:
NODE_ENV=production node --prof app.jse mettere un po' di carico sul server usando 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"e ottenere un output ab di:
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)Da questo output, vediamo che riusciamo a servire solo circa 5 richieste al secondo e che la richiesta media richiede poco meno di 4 secondi di andata e ritorno. In un esempio reale, potremmo fare molto lavoro in molte funzioni per conto di una richiesta utente, ma anche nel nostro semplice esempio, il tempo potrebbe essere perso compilando espressioni regolari, generando sali casuali, generando hash univoci dalle password utente, o all'interno del framework Express stesso.
Dal momento che abbiamo eseguito la nostra applicazione usando l'opzione --prof, è stato generato un file tick nella stessa directory della tua esecuzione locale dell'applicazione. Dovrebbe avere la forma isolate-0xnnnnnnnnnnnn-v8.log (dove n è una cifra).
Per dare un senso a questo file, dobbiamo utilizzare l'elaboratore di tick incluso nel binario Node.js. Per eseguire l'elaboratore, utilizzare il flag --prof-process:
node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txtAprire processed.txt nel tuo editor di testo preferito ti fornirà diversi tipi di informazioni. Il file è suddiviso in sezioni che a loro volta sono suddivise per linguaggio. Innanzitutto, guardiamo la sezione riepilogativa e vediamo:
[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% UnaccountedQuesto ci dice che il 97% di tutti i campioni raccolti si è verificato nel codice C++ e che, osservando altre sezioni dell'output elaborato, dovremmo prestare maggiore attenzione al lavoro svolto in C++ (al contrario di JavaScript). Con questo in mente, troviamo la sezione [C++] che contiene informazioni su quali funzioni C++ stanno richiedendo più tempo CPU e vediamo:
[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_mallocVediamo che le prime 3 voci rappresentano il 72,1% del tempo CPU impiegato dal programma. Da questo output, vediamo immediatamente che almeno il 51,8% del tempo CPU è occupato da una funzione chiamata PBKDF2 che corrisponde alla nostra generazione di hash da una password utente. Tuttavia, potrebbe non essere immediatamente ovvio come le due voci inferiori incidano sulla nostra applicazione (o se lo è, faremo finta di no per il bene dell'esempio). Per comprendere meglio la relazione tra queste funzioni, esamineremo la sezione [Bottom up (heavy) profile] che fornisce informazioni sui chiamanti principali di ciascuna funzione. Esaminando questa sezione, troviamo:
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:30L'analisi di questa sezione richiede un po' più di lavoro rispetto ai conteggi grezzi dei tick sopra. All'interno di ciascuno degli "stack di chiamate" sopra, la percentuale nella colonna parent indica la percentuale di campioni per cui la funzione nella riga sopra è stata chiamata dalla funzione nella riga corrente. Ad esempio, nello "stack di chiamate" intermedio sopra per _sha1_block_data_order, vediamo che _sha1_block_data_order si è verificato nell'11,9% dei campioni, cosa che sapevamo dai conteggi grezzi sopra. Tuttavia, qui possiamo anche dire che è sempre stato chiamato dalla funzione pbkdf2 all'interno del modulo crypto di Node.js. Vediamo che, allo stesso modo, _malloc_zone_malloc è stato chiamato quasi esclusivamente dalla stessa funzione pbkdf2. Quindi, usando le informazioni in questa vista, possiamo dire che il nostro calcolo hash dalla password dell'utente rappresenta non solo il 51,8% di sopra, ma anche tutto il tempo CPU nelle prime 3 funzioni più campionate, poiché le chiamate a _sha1_block_data_order e _malloc_zone_malloc sono state effettuate per conto della funzione pbkdf2.
A questo punto, è molto chiaro che la generazione di hash basata sulla password dovrebbe essere l'obiettivo della nostra ottimizzazione. Per fortuna, hai pienamente interiorizzato i benefici della programmazione asincrona e ti rendi conto che il lavoro per generare un hash dalla password dell'utente viene svolto in modo sincrono e quindi lega il loop degli eventi. Questo ci impedisce di lavorare su altre richieste in arrivo durante il calcolo di un hash.
Per rimediare a questo problema, apportiamo una piccola modifica agli handler di cui sopra per utilizzare la versione asincrona della funzione 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)
}
})
})Una nuova esecuzione del benchmark ab di cui sopra con la versione asincrona della tua app produce:
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)Evviva! La tua app ora serve circa 20 richieste al secondo, circa 4 volte di più rispetto alla generazione di hash sincrona. Inoltre, la latenza media è scesa dai 4 secondi precedenti a poco più di 1 secondo.
Si spera che, attraverso l'indagine sulle prestazioni di questo esempio (ammesso che sia artificioso), tu abbia visto come l'elaboratore di tick di V8 possa aiutarti a ottenere una migliore comprensione delle prestazioni delle tue applicazioni Node.js.
Potresti anche trovare utile come creare un flame graph.