Hiệu năng & profiling

Quy tắc đầu tiên khi tối ưu là đo trước. Đoán xem chỗ nào chậm gần như luôn sai: người ta tối ưu vòng lặp trong khi thời gian nằm ở một câu query thiếu index, hay viết lại một hàm trong khi phần lớn thời gian là chờ một API bên ngoài. Trang này giải thích cách tạo tải để đo, cách đọc profile CPU và flame graph, những chỗ hay chậm trong ứng dụng Node, và khi nào nên cache trong process. Phần chặn event loop có trang chính ở Chặn event loop & xử lý CPU, phần bộ nhớ ở Bộ nhớ & GC.

Quy trình

Xác định triệu chứng bằng con số: API nào, p50 hay p99, throughput bao nhiêu, lúc nào. "Hệ thống chậm" chưa phải là triệu chứng.
Chia thời gian của một request: bao nhiêu là chờ (database, API khác, mạng), bao nhiêu là CPU trên main thread, bao nhiêu là xếp hàng. Tracing (OpenTelemetry) cho bức tranh này ở production; event loop delay cho biết main thread có đang quá tải không (Event loop).
Nếu là chờ, tối ưu ở phía được chờ: query, index, gom lời gọi, cache (Phân tích bài toán).
Nếu là CPU, chạy profiler dưới tải để tìm hàm tốn thời gian.
Sửa một chỗ, đo lại trên cùng loại tải, so p99 chứ không chỉ trung bình (Latency).

Tạo tải để đo

Đo một request lẻ trên máy dev không nói được nhiều. Cần tạo tải giống thật:

autocannon (viết bằng Node) và wrk gửi request nhanh nhất có thể với một số connection cố định, hợp để đo throughput tối đa.
k6 viết kịch bản bằng JavaScript, đặt tốc độ request mỗi giây, hợp để mô phỏng người dùng thật và đo latency ở một mức tải cố định.

Ba lỗi hay gặp khi đo:

Công cụ đo kiểu closed-loop (gửi request tiếp chỉ khi request trước xong) báo latency đẹp hơn thật khi server bị treo, vì trong lúc treo nó cũng ngừng gửi. Lỗi này gọi là coordinated omission. Đo latency thì dùng tải open-loop với tốc độ cố định, như k6 hay wrk2 (Latency).
Không chạy nóng trước. V8 biên dịch tối ưu (JIT) những hàm chạy nhiều, nên vài trăm request đầu chậm hơn. Trên lab, request đầu tiên mất khoảng 7–8 ms, trong khi bình thường chỉ khoảng 2,7 ms. Bỏ giai đoạn khởi động ra khỏi số đo.
Client đo và server chạy chung máy thì tranh CPU với nhau, nên đo thấp hơn thực tế. Kết quả chỉ nên dùng để so sánh hai phiên bản với nhau.

Profiling CPU

Profiler của V8 lấy mẫu: cứ mỗi khoảng thời gian (mặc định 1 ms), nó ghi lại hàm nào đang chạy và chuỗi lời gọi dẫn tới đó. Hàm xuất hiện trong nhiều mẫu là hàm tốn nhiều CPU. Có mấy cách lấy profile:

node --cpu-prof app.js: ghi file .cpuprofile khi process thoát. Mở bằng tab Performance của Chrome DevTools, hoặc speedscope. File chỉ được ghi khi process thoát bình thường, nên với server phải bắt tín hiệu rồi gọi process.exit().
node --inspect app.js, mở chrome://inspect, tab Performance hay Profiler, bấm ghi trong lúc chạy tải.
clinic.js (clinic flame, clinic doctor) chạy app, tạo tải và vẽ sẵn flame graph hay chẩn đoán sơ bộ.
--prof của V8 cho file log ở mức thấp hơn, xử lý bằng node --prof-process.

Đọc flame graph

Flame graph vẽ mọi chuỗi lời gọi đã lấy mẫu, chồng lên nhau. Mỗi ô là một hàm, bề rộng là tổng thời gian của hàm đó cộng mọi hàm nó gọi, và ô bên dưới là hàm được ô bên trên gọi. Màu và thứ tự trái phải không có ý nghĩa thời gian. Cách đọc:

Tìm ô rộng mà không có ô con che kín bên dưới: đó là hàm có self time lớn, nơi CPU thật sự chạy.
Một ô rộng nhưng gần như toàn bộ bề rộng là các ô con thì bản thân nó không tốn, chỉ là nó gọi những thứ tốn.

Flame graph dưới dựng từ profile thật của một ứng dụng mẫu: mỗi request chờ "database" 2 ms, lọc và sắp xếp 2.000 đơn hàng, kiểm tra email bằng regex, JSON.stringify kết quả. Bấm vào một ô để phóng to:

Ẩn thời gian rảnh (idle) và phần của V8Đang xem: (root) (100,0%)

code của ứng dụng (app.mjs)code nội bộ của Node (timers, http, stream)native: V8, regex, JSON, ghi socket

Đọc từ trên xuống: ô dưới là hàm được ô trên gọi. Ô rộng là chỗ tốn thời gian. Tìm ô rộng mà không có ô con bên dưới che kín (self time lớn): đó là chỗ code thật sự chạy. Trong ứng dụng mẫu, phần của chính ứng dụng tốn nhiều nhất là: render (325 ms), (anonymous) (172 ms), filterOrders (104 ms), (anonymous) (49 ms), sortOrders (37 ms).

Dữ liệu thật từ --cpu-prof của lab/hieu-nang/app.mjs trong 4 giây chịu tải; nhánh dưới 0,3% đã bị bỏ, và các lời gọi trùng tên ở cùng một vị trí được gộp lại.

Trong profile này, khoảng 57% thời gian main thread rảnh ((idle), đang chờ I/O), và trong phần còn lại, JSON.stringify của hàm render và việc ghi response ra socket (writev) tốn nhiều nhất. Nhìn profile mới biết điều đó, chứ đọc code thì dễ nghĩ sắp xếp là chỗ tốn nhất.

Những chỗ hay chậm

Chỗ	Vì sao	Cách sửa
`JSON.stringify` / `JSON.parse` dữ liệu lớn	Tỉ lệ với kích thước, chạy trên main thread	Trả ít dữ liệu hơn (phân trang, chỉ lấy cột cần), fast-json-stringify với schema (số đo)
Log đồng bộ	`console.log` ghi vào file hay terminal là ghi đồng bộ	Logger bất đồng bộ (pino), ghi ra stdout là pipe rồi để hạ tầng gom; không log cả object lớn
Regex	Regex phức tạp, nhất là khi bị ReDoS	Giới hạn độ dài input, viết lại regex (ReDoS)
Hàm `…Sync`, thư viện đồng bộ	Chặn main thread	Bản bất đồng bộ; chỉ dùng `…Sync` lúc khởi động
N+1 query, query chậm	Thời gian chờ chứ không phải CPU, profiler CPU không thấy	Tracing, `EXPLAIN` (Bẫy của ORM)
Tạo object, closure trong vòng lặp nóng	Tăng áp lực lên GC	Chỉ tối ưu khi profile chỉ ra
Mở connection mới mỗi lần gọi	Mỗi lần bắt tay TCP, TLS	Keep-alive, connection pool

Về log, tài liệu Node nói rõ process.stdout ghi đồng bộ khi nối vào file (trên mọi hệ điều hành) và vào terminal (trên Linux, macOS), còn khi nối vào pipe thì bất đồng bộ trên Linux, macOS. Trên lab, ghi một dòng console.log mỗi request vào file làm throughput giảm khoảng 5% (khoảng 8.700 xuống 8.200 request mỗi giây), còn gom log trong bộ nhớ rồi ghi theo lô thì gần như không tốn gì. Với log dài hơn hay đĩa chậm hơn, chênh lệch lớn hơn nhiều.

Cache trong process hay Redis

Khi một phép tính hay một query lặp lại nhiều, cache cho kết quả lại là cách nhanh nhất. Có hai chỗ để cache:

	Cache trong process (`Map`, lru-cache)	Redis
Tốc độ đọc	Vài trăm ns, không qua mạng	Khoảng 0,1–1 ms, một vòng mạng (Redis)
Dùng chung giữa các instance	Không: mỗi instance một bản, mỗi bản có thể khác nhau	Có
Xoá khi dữ liệu đổi	Khó: phải báo cho mọi instance	Xoá một key
Bộ nhớ	Tính vào heap, làm GC chậm hơn, phải giới hạn kích thước	Riêng
Mất khi	Restart, deploy	Redis restart (tuỳ cấu hình lưu bền)

Cache trong process hợp với dữ liệu đọc rất nhiều, ít đổi, và chấp nhận mỗi instance lệch nhau vài giây: cấu hình, danh mục, bảng tỉ giá. Luôn có TTL ngắn và giới hạn số phần tử (Bộ nhớ & GC). Dữ liệu cần nhất quán giữa các instance thì dùng Redis, hoặc kết hợp hai tầng (Cache).

Ghi nhớ

Đo trước khi tối ưu: chia thời gian request thành chờ, CPU và xếp hàng; chỉ chạy profiler CPU khi phần CPU đáng kể.
Tạo tải giống thật; đo latency bằng tải open-loop, chạy nóng trước, và chỉ so sánh tương đối khi client và server chung máy.
--cpu-prof, --inspect với Chrome DevTools, clinic.js; trong flame graph, tìm ô rộng không có ô con che kín.
Chỗ hay chậm: JSON lớn, log đồng bộ (console.log vào file là ghi đồng bộ), regex, hàm …Sync, N+1 query.
Cache trong process nhanh nhưng mỗi instance một bản và tốn heap; cần nhất quán giữa các instance thì dùng Redis.

Nguồn tham khảo

Đã đối chiếu (đọc nguồn ngày 2026-10-26):

Nguồn	Dùng cho phần
Node.js docs, Process: A note on process I/O	`process.stdout` ghi đồng bộ với file, với terminal trên POSIX; bất đồng bộ với pipe trên POSIX
Node.js, Profiling Node.js Applications	`--prof` và `--prof-process`
Node.js docs, `--cpu-prof`	Ghi profile khi thoát, khoảng lấy mẫu mặc định 1.000 µs (đã đối chiếu khi viết trang Chặn event loop)

Kiểm bằng lab: khởi động lạnh, ảnh hưởng của log, profile và flame graph. Từ kiến thức chung, chưa đối chiếu lần này: autocannon, wrk, k6, clinic.js, speedscope, fast-json-stringify, pino; tốc độ đọc của cache trong process.

Số đo chi tiết

Kết quả chạy lab/hieu-nang/run.mjs (MacBook M2, Node 24.14, hai lượt)

Khởi động lạnh, một connection, gửi lần lượt: request đầu tiên 7,0–8,1 ms; trung vị 200 request đầu 2,64 ms; trung vị 200 request sau 3.000 request 2,66–2,73 ms.

Log mỗi request, 32 connection, 4 giây:

Cách	Request/s	p50	p99
Không log	8.671–8.692	3,6 ms	6,3–9,2 ms
`console.log` vào file	8.195–8.227	3,8–4,0 ms	7,8–8,6 ms
Gom log, ghi theo lô mỗi 100 ms	8.626–8.696	3,7 ms	6,1–7,1 ms

Profile khi chịu tải: 3.225 mẫu trong khoảng 4 giây. Self time lớn nhất: (idle) 57%, hàm render (JSON.stringify) 8%, writev (ghi socket) 5,6%, (program) 5,2%, handler 4,2%, filterOrders 2,8%, regex kiểm email 1,4%.

Code đã dùng để chạy thử

Chạy bằng npm run lab -- hieu-nang, chỉ cần Node.js, khoảng 25 giây. Lệnh này ghi đè docs/.vitepress/theme/data/flame-sample.js. Xem Lab.

lab/hieu-nang/app.mjs: ứng dụng mẫu

// Ứng dụng mẫu cho lab/hieu-nang, chạy trong process con. Đối số: chế độ log.
//   GET /orders  "query" 2 ms (chờ timer), lọc + sắp xếp 2.000 đơn, kiểm tra email bằng regex, JSON.stringify, ghi log
// Chế độ log:
//   none     không ghi log
//   console  console.log một dòng JSON mỗi request (stdout được chuyển hướng vào file)
//   buffer   gom log trong bộ nhớ, ghi ra file theo lô mỗi 100 ms (cách các logger như pino làm với đích bất đồng bộ)
import http from 'node:http'
import { createWriteStream } from 'node:fs'

const mode = process.argv[2] || 'none'
const orders = Array.from({ length: 2000 }, (_, i) => ({ id: i, userId: i % 300, email: `user${i % 300}@shop.vn`, amount: (i * 7919) % 100000, status: ['paid', 'pending', 'shipped'][i % 3], items: [{ sku: 'A' + (i % 50), qty: 1 + (i % 3) }] }))
const EMAIL = /^[a-z0-9._%+-]+@[a-z0-9.-]+\.[a-z]{2,}$/i

function filterOrders(userId) { return orders.filter((o) => o.userId === userId || o.amount > 99000) }
function sortOrders(list) { return [...list].sort((a, b) => b.amount - a.amount) }
function validate(list) { return list.filter((o) => EMAIL.test(o.email)) }
function render(list) { return JSON.stringify({ total: list.length, orders: list }) }

let buf = []
const out = mode === 'buffer' ? createWriteStream(process.argv[3]) : null
if (out) setInterval(() => { if (buf.length) { out.write(buf.join('')); buf = [] } }, 100).unref()
function log(obj) {
  if (mode === 'console') console.log(JSON.stringify(obj))
  else if (mode === 'buffer') buf.push(JSON.stringify(obj) + '\n')
}

// --cpu-prof chỉ ghi file khi process thoát bình thường; SIGINT mặc định giết process ngay nên phải tự exit
process.on('SIGINT', () => process.exit(0))

http.createServer(async (req, res) => {
  const t0 = performance.now()
  await new Promise((r) => setTimeout(r, 2)) // chờ database
  const userId = Number(new URL(req.url, 'http://x').searchParams.get('u') ?? 1)
  const body = render(validate(sortOrders(filterOrders(userId))))
  res.setHeader('Content-Type', 'application/json')
  res.end(body)
  log({ level: 'info', msg: 'request', path: req.url, ms: performance.now() - t0, time: Date.now() })
}).listen(0, '127.0.0.1', function () { process.send(this.address().port) })

lab/hieu-nang/run.mjs

// Trang nodejs/hieu-nang. Chỉ cần Node.js, khoảng 40 giây.
//   1. Khởi động lạnh: latency của 200 request đầu so với sau khi đã chạy nóng (JIT)
//   2. Throughput theo cách ghi log: không log, console.log vào file, gom log ghi theo lô
//   3. --cpu-prof khi có tải, đổi file .cpuprofile thành cây cho mô phỏng flame graph
//      (ghi đè docs/.vitepress/theme/data/flame-sample.js)
import http from 'node:http'
import { fork } from 'node:child_process'
import { openSync, closeSync, mkdtempSync, readdirSync, readFileSync, rmSync, writeFileSync, statSync } from 'node:fs'
import { tmpdir } from 'node:os'
import { join } from 'node:path'

const dir = mkdtempSync(join(tmpdir(), 'perf-'))
const app = new URL('./app.mjs', import.meta.url).pathname
async function start(args, execArgv = [], stdoutFile) {
  const fd = stdoutFile ? openSync(stdoutFile, 'w') : 'ignore'
  const child = fork(app, args, { execArgv, stdio: ['ignore', fd, 'inherit', 'ipc'] })
  const port = await new Promise((r) => child.once('message', r))
  if (typeof fd === 'number') closeSync(fd)
  return { child, port }
}
const stop = (child) => new Promise((r) => { child.once('exit', r); child.kill('SIGINT') })
async function load(port, conns, seconds) {
  const agent = new http.Agent({ keepAlive: true, maxSockets: conns })
  const lat = []
  const end = performance.now() + seconds * 1000
  const get = () => new Promise((res, rej) => http.get({ host: '127.0.0.1', port, path: `/orders?u=${Math.floor(Math.random() * 300)}`, agent }, (r) => { r.resume(); r.on('end', res) }).on('error', rej))
  await Promise.all(Array.from({ length: conns }, async () => { while (performance.now() < end) { const t = performance.now(); await get(); lat.push(performance.now() - t) } }))
  agent.destroy()
  lat.sort((a, b) => a - b)
  return { rps: lat.length / seconds, p50: lat[Math.floor(lat.length / 2)], p99: lat[Math.floor(lat.length * 0.99)] }
}
const ms = (v) => v.toFixed(v < 10 ? 2 : 1).replace('.', ',') + ' ms'

try {
  console.log('\n=== 1. Khởi động lạnh: một connection, gửi lần lượt ===')
  {
    const { child, port } = await start(['none'])
    const agent = new http.Agent({ keepAlive: true, maxSockets: 1 })
    const one = () => new Promise((res) => { const t = performance.now(); http.get({ host: '127.0.0.1', port, path: '/orders?u=1', agent }, (r) => { r.resume(); r.on('end', () => res(performance.now() - t)) }) })
    const first = []; for (let i = 0; i < 200; i++) first.push(await one())
    for (let i = 0; i < 3000; i++) await one()
    const warm = []; for (let i = 0; i < 200; i++) warm.push(await one())
    const med = (a) => [...a].sort((x, y) => x - y)[Math.floor(a.length / 2)]
    console.log(`request đầu tiên ${ms(first[0])}; trung vị 200 request đầu ${ms(med(first))}; trung vị 200 request sau 3.000 request ${ms(med(warm))}`)
    agent.destroy(); await stop(child)
  }

  console.log('\n=== 2. Ghi log mỗi request: 32 connection, 4 giây ===')
  for (const [label, args] of [['Không log', ['none']], ['console.log vào file (stdout chuyển hướng)', ['console']], ['Gom log, ghi theo lô mỗi 100 ms', ['buffer', join(dir, 'buf.log')]]]) {
    const f = join(dir, 'stdout.log')
    const { child, port } = await start(args, [], f)
    await load(port, 8, 1)
    const r = await load(port, 32, 4)
    await stop(child)
    const size = args[0] === 'buffer' ? statSync(args[1]).size : statSync(f).size
    console.log(`${label.padEnd(44)} ${Math.round(r.rps).toLocaleString('vi-VN').padStart(6)} request/s, p50 ${ms(r.p50)}, p99 ${ms(r.p99)}, log ${(size / 1e6).toFixed(1).replace('.', ',')} MB`)
  }

  console.log('\n=== 3. --cpu-prof khi có tải ===')
  const profDir = join(dir, 'prof')
  const { child, port } = await start(['none'], ['--cpu-prof', '--cpu-prof-dir', profDir])
  await load(port, 32, 4)
  await stop(child)
  const prof = JSON.parse(readFileSync(join(profDir, readdirSync(profDir).find((f) => f.endsWith('.cpuprofile'))), 'utf8'))
  // Tính self time của từng node trong cây lời gọi từ mẫu
  const byId = new Map(prof.nodes.map((n) => [n.id, { ...n, self: 0 }]))
  prof.samples.forEach((id, i) => { byId.get(id).self += (prof.timeDeltas[i] || 0) / 1000 })
  const nameOf = (n) => {
    const { functionName, url, lineNumber } = n.callFrame
    const file = url ? url.split('/').pop() : ''
    return (functionName || (url ? '(anonymous)' : n.callFrame.functionName || '(program)')) + (file ? ` ${file}:${lineNumber + 1}` : '')
  }
  // Dựng cây có tổng thời gian, gộp các con trùng tên, bỏ nhánh nhỏ hơn 0,3% tổng
  const total = [...byId.values()].reduce((s, n) => s + n.self, 0)
  const build = (n) => {
    const kids = (n.children || []).map((c) => build(byId.get(c)))
    const merged = new Map()
    for (const k of kids) { const m = merged.get(k.name); if (m) { m.value += k.value; m.self += k.self; m.children.push(...k.children) } else merged.set(k.name, k) }
    const children = [...merged.values()]
    const value = n.self + children.reduce((s, c) => s + c.value, 0)
    return { name: nameOf(n), self: n.self, value, children }
  }
  const prune = (n) => ({ name: n.name, value: Math.round(n.value * 10) / 10, self: Math.round(n.self * 10) / 10, children: n.children.filter((c) => c.value >= total * 0.003).sort((a, b) => b.value - a.value).map(prune) })
  const root = prune(build(byId.get(prof.nodes[0].id)))
  root.name = '(root)'
  const out = new URL('../../docs/.vitepress/theme/data/flame-sample.js', import.meta.url)
  writeFileSync(out, `// Sinh bởi lab/hieu-nang/run.mjs: --cpu-prof của lab/hieu-nang/app.mjs khi chịu tải 32 connection trong 4 giây.\n// Đơn vị ms; nhánh nhỏ hơn 0,3% tổng thời gian đã bị bỏ.\nexport const FLAME = ${JSON.stringify(root)}\n`)
  const selfBy = new Map()
  for (const n of byId.values()) { const k = nameOf(n); selfBy.set(k, (selfBy.get(k) || 0) + n.self) }
  console.log(`${prof.samples.length} mẫu, ${Math.round(total)} ms. 8 hàm có self time lớn nhất:`)
  for (const [k, v] of [...selfBy].sort((a, b) => b[1] - a[1]).slice(0, 8)) console.log(`${((v / total) * 100).toFixed(1).replace('.', ',').padStart(5)}%  ${k}`)
  console.log(`Đã ghi cây flame graph vào ${out.pathname.split('/docs/')[1]}`)
} finally {
  rmSync(dir, { recursive: true, force: true })
}

Hiệu năng & profiling ​

Quy trình ​

Tạo tải để đo ​

Profiling CPU ​

Đọc flame graph ​

Những chỗ hay chậm ​

Cache trong process hay Redis ​

Nguồn tham khảo ​

Số đo chi tiết ​

Code đã dùng để chạy thử ​