Performance and profiling

เมื่อฐานข้อมูลรู้สึกช้า ความล่อใจคือเดา: เพิ่ม server เพิ่มหน่วยความจำ เพิ่ม index ตรงไหนสักแห่งแล้วหวังว่าจะดีขึ้น สิ่งที่มืออาชีพทำคือตรงกันข้าม — วัดก่อน MongoDB มีสองเครื่องมือ database profiler บันทึก operation ที่รันจริงและใช้เวลาเท่าไร คุณจึงเห็นว่า query ไหนเป็นปัญหา และ explain บอกว่า ทำไม query หนึ่งจึงช้า โดยแสดง plan ที่ server เลือก

fence ที่มี path comment รันบน replica set โหนดเดียวของคอร์ส (mongo 8.3.11, mongosh 2.11.1, Node driver 7.7.0, เครื่อง Mac นี้); fence ที่ระบุ lab รันบน container mongo:8.3.11 แบบ standalone ชั่วคราว จำกัด 512 MB และ WiredTiger cache 0.25 GB (mongodb-b3-perf ลบทิ้งหลังใช้) เพราะมันเปลี่ยนค่าระดับ server (slowms), รีสตาร์ท server หรือวัดตัวนับระดับ server แท็บ Python/Go/Rust สะท้อนการเรียกที่ตรวจแล้วใน shell/Node และไม่ได้ถูกรันโดยตัวตรวจอัตโนมัติของคอร์ส

เวลาไปอยู่ที่ไหน

query ช้าส่วนใหญ่มาจากหนึ่งในสองสาเหตุ: query อ่าน document มากกว่าที่คืนมาก หรือข้อมูลที่ต้องใช้ไม่อยู่ในหน่วยความจำและต้องดึงจากดิสก์

flowchart TB
  subgraph Slow["No index — COLLSCAN"]
    Q1["Find members joined in 2023"] --> R1["Read every document"]
    R1 --> F1["Discard the non-matches"]
    F1 --> O1["Return the matches — slow"]
  end
  subgraph Fast["With an index — IXSCAN"]
    Q2["Find members joined in 2023"] --> R2["Seek the index to 2023"]
    R2 --> F2["Read only the matching documents"]
    F2 --> O2["Return them — fast"]
  end

ไม่มี index query อ่านทุกอย่างแล้วทิ้งส่วนใหญ่; มี index มันอ่านเฉพาะสิ่งที่คืน

สาเหตุที่สองคือ working set: ส่วนของข้อมูลและ index ที่ query แตะจริง ๆ เมื่อมันพอดีใน RAM การอ่านมาจากหน่วยความจำ เมื่อไม่พอดี ทุก miss กลายเป็นการอ่านดิสก์ demo ของ cache ด้านล่างทำให้เห็นชัด

เปิด profiler

profiler เขียนหนึ่ง document ต่อหนึ่ง operation ที่บันทึกลงใน collection system.profile แบบ capped ในแต่ละ database Level 1 บันทึก operation ที่ช้ากว่า slowms; level 2 บันทึกทุกอย่าง (เฉพาะตอนพัฒนา); level 0 ปิด ด้านล่าง level 2 บน database ของบทเรียนที่มีสมาชิก 50 000 คน — ปลอดภัยบน server ที่ใช้ร่วมกัน เพราะกระทบเฉพาะ database นี้ — แล้วดู query ล่าสุดที่ช้าที่สุด:

const docs = Array.from({ length: 50000 }, (_, i) => ({ name: "m" + i, joined: 2015 + (i % 10), city: "c" + (i % 200), fines: i % 7 }));
db.members.insertMany(docs);

db.setProfilingLevel(2);
db.members.find({ joined: 2023 }).batchSize(5000).toArray();   // no index yet; one batch = one profile entry
db.setProfilingLevel(0);

const e = db.system.profile.find({ op: "query", ns: db.getName() + ".members" }).sort({ ts: -1 }).limit(1).toArray()[0];
console.log({ op: e.op, millis: e.millis, planSummary: e.planSummary, docsExamined: e.docsExamined, keysExamined: e.keysExamined, nreturned: e.nreturned });
assert.strictEqual(e.planSummary, "COLLSCAN");
assert.ok(e.docsExamined >= 49000);

const members = db.collection("members");
await members.insertMany(Array.from({ length: 50000 }, (_, i) => ({ name: "m" + i, joined: 2015 + (i % 10), city: "c" + (i % 200), fines: i % 7 })));

await db.command({ profile: 2 });
await members.find({ joined: 2023 }, { batchSize: 5000 }).toArray();
await db.command({ profile: 0 });

const [e] = await db.collection("system.profile")
  .find({ op: "query", ns: db.databaseName + ".members" }).sort({ ts: -1 }).limit(1).toArray();
console.log({ op: e.op, millis: e.millis, planSummary: e.planSummary, docsExamined: e.docsExamined, nreturned: e.nreturned });
if (e.planSummary !== "COLLSCAN" || e.docsExamined < 49000) throw new Error("expected a full collection scan");

db.command("profile", 1, slowms=100)
status = db.command("profile", -1)
print(status)

if err := db.RunCommand(ctx, bson.D{
    {Key: "profile", Value: 1},
    {Key: "slowms", Value: 100},
}).Err(); err != nil {
    return err
}

db.run_command(doc! { "profile": 1, "slowms": 100 }).await?;

{
  op: 'query',
  millis: 37,
  planSummary: 'COLLSCAN',
  docsExamined: 49999,
  keysExamined: 0,
  nreturned: 5000
}

{
  op: 'query',
  millis: 31,
  planSummary: 'COLLSCAN',
  docsExamined: 49999,
  nreturned: 5000
}

ฟิลด์ที่ต้องอ่านคือ millis, docsExamined เทียบกับ nreturned (อ่าน 49 999 เพื่อคืน 5 000) และ planSummary (COLLSCAN คือ scan ทั้ง collection) มีสิ่งหนึ่งที่ร่างแรกของบทเรียนนี้ประหลาดใจ: profiler บันทึก หนึ่ง entry ต่อ batch find().toArray() ธรรมดาบน collection ของ lab ที่มี 200 000 document ได้ entry query ที่ nreturned: 101, docsExamined: 1009 (มันหยุด scan เมื่อได้ batch แรกแล้ว) และ entry getmore แยกต่างหากที่ nreturned: 19899 สำหรับส่วนที่เหลือ fence จึงใช้ batchSize(5000) เพื่อให้ผลทั้งหมดเป็น entry เดียว เพิ่ม index แล้วรันอีกครั้ง:

db.members.createIndex({ joined: 1 });

db.setProfilingLevel(2);
const n = db.members.find({ joined: 2023 }).batchSize(5000).toArray().length;
db.setProfilingLevel(0);

const e = db.system.profile.find({ op: "query", ns: db.getName() + ".members" }).sort({ ts: -1 }).limit(1).toArray()[0];
console.log({ millis: e.millis, planSummary: e.planSummary, keysExamined: e.keysExamined, docsExamined: e.docsExamined, nreturned: e.nreturned });
assert.strictEqual(e.planSummary, "IXSCAN { joined: 1 }");
assert.strictEqual(e.docsExamined, n);

{
  millis: 42,
  planSummary: 'IXSCAN { joined: 1 }',
  keysExamined: 5000,
  docsExamined: 5000,
  nreturned: 5000
}

ตอนนี้ docsExamined เท่ากับ nreturned: index อ่านตรงกับที่ query คืน (เวลาบน collection 50 000 document เป็นระดับมิลลิวินาทีทั้งสองแบบ; จำนวน คือสัญญาณที่ขยายตามขนาดข้อมูล)

`slowms`, log และต้นทุนของ profiler

Level 1 บันทึกเฉพาะ operation ที่ช้ากว่า slowms (ค่าเริ่มต้น 100 ms) เกณฑ์เดียวกันนี้ยังตัดสินว่า server จะเขียนอะไรลง log เป็นบรรทัด "Slow query" แม้ profiler อยู่ level 0 การรัน lab ด้วย slowms: 20 บน collection 200 000 document:

// mongosh/perf-slowms.js @skip-verify lab: sets the server-wide slowms on a throwaway standalone
db.setProfilingLevel(0, { slowms: 20 });
console.log(db.getProfilingStatus());
db.members.find({ fines: 99 }).toArray();       // COLLSCAN over all 200 000 documents, no match
db.members.find({ name: "m1" }).limit(1).toArray();   // stops at the first hit: fast
console.log("profile entries at level 0:", db.system.profile.countDocuments());
db.setProfilingLevel(1, { slowms: 20 });
db.members.find({ fines: 99 }).toArray();
db.members.find({ name: "m1" }).limit(1).toArray();
console.log("profile entries at level 1:", db.system.profile.find({}, { op: 1, millis: 1, planSummary: 1 }).toArray());
const p = db.system.profile.stats();
console.log({ capped: p.capped, maxSizeBytes: p.maxSize });

{
  was: 0,
  slowms: 20,
  slowinprogms: Long('5000'),
  sampleRate: 1,
  ok: 1
}
profile entries at level 0: 0
profile entries at level 1: [ { op: 'query', millis: 103, planSummary: 'COLLSCAN' } ]
{ capped: true, maxSizeBytes: 1048576 }

และบรรทัดใน log ของ server สำหรับตัวที่ช้า อ่านกลับจาก log ในหน่วยความจำของ server (getLog; JSON เดียวกันนี้ไปที่ไฟล์ log หรือ docker logs) ตัดเหลือ key ที่น่าสนใจ:

// mongosh/perf-slowlog.js @skip-verify lab: reads the log of the throwaway server (real output below)
const line = db.adminCommand({ getLog: "global" }).log.filter((l) => l.includes("Slow query") && l.includes('"fines":99')).pop();
const j = JSON.parse(line);
console.log({ msg: j.msg, ns: j.attr.ns, planSummary: j.attr.planSummary, keysExamined: j.attr.keysExamined, docsExamined: j.attr.docsExamined, nreturned: j.attr.nreturned, durationMillis: j.attr.durationMillis });

2
{"msg":"Slow query","ns":"library.members","planSummary":"COLLSCAN","keysExamined":0,"docsExamined":200000,"nreturned":0,"durationMillis":103}

สามข้อเท็จจริง: (1) ที่ level 0 query ช้าก็ยังถูก log แต่ไม่ถูก profile; (2) ที่ level 1 มีเฉพาะ operation ที่ช้าถูกบันทึก การค้น _id ไม่ถูกบันทึก; (3) system.profile เป็น collection แบบ capped ที่มีขนาดคงที่ (1 MB โดยค่าเริ่มต้นในการรันนี้) entry เก่าจึงหลุดออก

ดู operation ที่กำลังรัน: `currentOp`

profiler คือประวัติ; currentOp คือปัจจุบัน การรัน lab เริ่ม query ที่ช้าโดยตั้งใจ ($where กับ sleep) บน connection หนึ่งและตรวจดูจากอีกอัน แล้ว kill มัน:

// mongosh/perf-currentop.js @skip-verify lab: needs two connections (real output below)
// connection A (blocks):  db.members.find({ $where: "sleep(4000) || true" }).toArray()
// connection B:
const op = db.currentOp({ ns: /members/, op: "query", secs_running: { $gte: 1 } }).inprog[0];
console.log({ op: op.op, ns: op.ns, secs_running: op.secs_running, planSummary: op.planSummary, opid: op.opid });
db.killOp(op.opid);

{
  op: 'query',
  ns: 'library.members',
  secs_running: Long('1'),
  planSummary: 'COLLSCAN',
  opid: 31745
}

WiredTiger cache และ working set

storage engine เก็บ page ที่ใช้ล่าสุดใน cache ของตัวเอง ขนาดเริ่มต้นราวครึ่งหนึ่งของ RAM (ที่นี่จำกัดที่ 0.25 GB) query บนข้อมูลที่ไม่อยู่ใน cache ต้องอ่าน page จากดิสก์ lab รีสตาร์ท server (cache เย็น) รัน aggregate scan เดียวกันสองครั้ง และอ่านตัวนับของ cache รอบ ๆ:

// app/perf-cache.mjs @skip-verify lab: run right after `docker restart` of the throwaway server (real output below)
const stats = async () => {
  const c = (await db.admin().command({ serverStatus: 1 })).wiredTiger.cache;
  return { maxBytes: c["maximum bytes configured"], inCacheBytes: c["bytes currently in the cache"], pagesReadIntoCache: c["pages read into cache"] };
};
const scan = async () => { const t = Date.now(); await db.collection("members").aggregate([{ $group: { _id: "$city", n: { $sum: 1 }, fines: { $sum: "$fines" } } }]).toArray(); return Date.now() - t; };
console.log("before", await stats());
console.log("cold scan ms:", await scan());
console.log("warm scan ms:", await scan());
console.log("after ", await stats());

before { maxBytes: 268435456, inCacheBytes: 57465, pagesReadIntoCache: 21 }
cold scan ms: 97
warm scan ms: 63
after  {
  maxBytes: 268435456,
  inCacheBytes: 19855589,
  pagesReadIntoCache: 346
}

scan แรกหลังรีสตาร์ทต้องอ่าน page เข้า cache (pagesReadIntoCache กระโดดขึ้น) และช้ากว่าครั้งที่สองที่ให้บริการจากหน่วยความจำ เมื่อ working set ใหญ่กว่า cache ทุก scan จะหน้าตาเหมือนตัวเย็น — ทางแก้คือ RAM เพิ่ม, document เล็กลง (projection, ฟิลด์น้อยลง) หรือ index ที่แตะ page น้อยลง

connection pool: client เดียว ไม่ใช่หนึ่งตัวต่อ request

driver เก็บ pool ของ connection และใช้ซ้ำ ความผิดพลาดคลาสสิกคือสร้าง client ภายใน request handler ซึ่งต้องจ่าย handshake ของ TCP (และ TLS/auth) ทุกครั้ง และอาจทำให้ถึงขีดจำกัด connection ของ server

🐛 หา bug ในโค้ดนี้

// AI comment: "connect per request for isolation; the driver cleans up"
app.get("/members/:id", async (req, res) => {
const client = new MongoClient(process.env.MONGO_URL);
await client.connect();
const doc = await client.db("library").collection("members").findOne({ _id: req.params.id });
await client.close();
res.json(doc);
});

เฉลย

แต่ละ request เปิด (และปิด) connection ของตัวเอง วัดผล (lab, lookup ตามลำดับ 300 ครั้งกับ standalone, serverStatus().connections.totalCreated ก่อน/หลัง):

// app/perf-pool.mjs @skip-verify lab: reads server-wide connection counters (real output below)
import { MongoClient } from "mongodb";
const uri = "mongodb://localhost:27303/";
const created = async (c) => (await c.db("admin").command({ serverStatus: 1 })).connections.totalCreated;
const watcher = new MongoClient(uri); await watcher.connect();

let before = await created(watcher);
let t = Date.now();
for (let i = 0; i < 300; i++) {                        // the bug: a client per request
  const c = new MongoClient(uri); await c.connect();
  await c.db("library").collection("members").findOne({ name: "m" + i });
  await c.close();
}
const perRequest = { ms: Date.now() - t, newConnections: (await created(watcher)) - before };

const shared = new MongoClient(uri); await shared.connect();   // the fix: one client for the process
before = await created(watcher);
t = Date.now();
for (let i = 0; i < 300; i++) await shared.db("library").collection("members").findOne({ name: "m" + i });
const sharedRun = { ms: Date.now() - t, newConnections: (await created(watcher)) - before };
console.log({ perRequest, shared: sharedRun });
await shared.close(); await watcher.close();

{
  perRequest: { ms: 5067, newConnections: 600 },
  shared: { ms: 823, newConnections: 0 }
}

วิธีแก้ที่ใช้บ่อย

เพิ่ม index สำหรับฟิลด์ที่ query filter และ sort — วิธีแก้ที่มีผลสูงสุดอย่างเดียว (COLLSCAN เป็น IXSCAN, docsExamined จาก 49 999 เหลือ 5 000 ข้างบน)
project ให้น้อยลง เพื่อให้ย้ายไบต์น้อยลงและ query อาจตอบจาก index ได้
จำกัดผลลัพธ์ ด้วย limit
ใช้ client เดียว ต่อโปรเซส (วัดข้างบน)

ใน Compass / Atlas: แท็บ Explain Plan ของ Compass รัน explain ให้ query และติดธง collection scan; Atlas มี Performance Advisor ที่เสนอ index จากทราฟฟิกจริง — ทั้งสองเป็น UI ที่ครอบกลไกที่แสดงในนี้ และชื่อแผงเปลี่ยนไปตามรุ่น

เคล็ดลับและข้อควรระวัง

ใช้ level 1 กับ slowms ที่เหมาะสมใน production Level 2 บันทึกทุกอย่างและบน server ที่ยุ่งจะท่วม collection แบบ capped
slowms เป็นค่า ระดับ server: เปลี่ยนใน database หนึ่งเปลี่ยนให้ทุกตัว (และให้ log ด้วย) ลองบน server ชั่วคราวก่อน
system.profile เป็น capped และแยกตาม database; อ่านมันเร็ว ๆ หลังทำซ้ำปัญหา
profiler บอก ว่า query ไหนช้า; explain บอก ว่าทำไม
อัตราส่วน docsExamined ต่อ nreturned ที่สูงคือสัญญาณเดี่ยวที่ชัดที่สุดของ index ที่ขาดหรือผิด

Mental Model

งานด้าน performance คือลูปบน ตัวนับสามตัว: server ตรวจ เท่าไร (keysExamined, docsExamined), คืน เท่าไร (nreturned) และ page อยู่ในหน่วยความจำ หรือไม่ (ตัวนับของ cache) query ที่สุขภาพดีตรวจเท่ากับที่คืน; ที่ไม่ดีตรวจทุกอย่าง (ขาด index) หรือรอดิสก์ (cache เย็นหรือเล็กเกินไป) profiler และ currentOp บอกว่า operation ไหน explain บอกว่าทำไม และ pool บอกว่า client กำลังสร้างโหลดเองหรือไม่

ข้อแลกเปลี่ยน

ตัวเลือก	ประโยชน์	ต้นทุน
Profiler level `2`	บันทึกทุก operation รวมถึงที่เกิดเป็นครั้งคราว	overhead และ collection แบบ capped ที่เต็มและ entry หลุดเร็ว
Profiler level `1` กับ `slowms`	ถูกพอที่จะเปิดทิ้งไว้	พลาด operation ที่ต่ำกว่าเกณฑ์; `slowms` ยังเปลี่ยน log ของทั้ง server
Slow-query log อย่างเดียว (level `0`)	ไม่มี collection profile ให้ดูแล	entry อยู่ใน log ไม่ใช่ document ที่ query ได้
Index ทุก filter	การอ่านตรวจเท่ากับที่คืน	ทุกการเขียนจ่ายค่า index ทุกตัว (ดูโมดูล indexes)

Common Misconceptions

“profiler ที่ level 0 คือปิด” — slow-query log ยังบันทึกทุกอย่างที่ช้ากว่า slowms
“ตั้ง slowms ใน database หนึ่งมีผลเฉพาะที่” — มันเป็นระดับ server
“system.profile เก็บประวัติ” — มันเป็น capped และหมุนเวียน; entry ข้างบนหายไปเมื่อมีตัวใหม่เข้ามา
“query แรกที่เย็นแปลว่า index แย่” — scan แรกหลังรีสตาร์ทอ่าน page เข้า cache; เปรียบเทียบรอบอุ่น
“สร้าง client ต่อ request ปลอดภัยกว่า” — มันทำให้ connection ใหม่เพิ่มขึ้นมาก (ดูรอบ pool ข้างบน) และลูปช้าลง; client ที่ใช้ร่วมกันเป็นแบบแผน
“index ที่มีอยู่จะถูกใช้เสมอ” — planner เลือก; ดู planSummary ใน profile entry แทนการสมมติ

แท็บ Python/Go/Rust สะท้อนพฤติกรรมที่ตรวจแล้วใน shell/Node; ไม่ได้ถูกรันโดยตัวตรวจอัตโนมัติของคอร์ส