Slow Queries

Laporan “aplikasi lambat” hampir selalu berujung pada satu-dua query yang memindai terlalu banyak document — tetapi menemukannya butuh alur kerja, bukan tebakan. Alur triage-nya pendek: tangkap query yang mencurigakan lewat profiler, ukur biayanya lewat explain, lalu perbaiki dengan index dan buktikan perbaikannya dengan explain kedua. Chapter ini menjalankan seluruh alur itu dalam satu sesi utuh di atas 5000 document — dari COLLSCAN sampai IXSCAN — sementara pendalaman tiap alat (level profiler, membaca execution stats, perencanaan index) sudah dibahas penuh di Section Performance dan Optimization.

Peta materi Chapter ini:

• Siklus lengkap: profiler menyala → query → catatan system.profile → explain → index → verifikasi ulang.
• Membaca biaya utama: docsExamined versus nreturned.
• Bukti perbaikan yang bisa diukur, bukan sekadar “terasa lebih cepat”.

Data dan Profiler Menyala #

Siapkan collection besar untuk skala latihan — 5000 document dimasukkan per seribu agar tidak membebani memori:

use latihan_trouble
db.buku_besar.drop()
let batch = []
for (let i = 0; i < 5000; i++) {
  batch.push({ judul: "Buku Nomor " + i, penulis: "Penulis " + (i % 40), harga: 50000 + (i % 500) * 100, rak: "R" + (i % 60) })
  if (batch.length === 1000) { db.buku_besar.insertMany(batch); batch = [] }
}
print("jumlah document: " + db.buku_besar.countDocuments({}))

Output yang Dihasilkan:

switched to db latihan_trouble
true

[]
jumlah document: 5000

Baris [] adalah nilai akhir variabel batch — loop menutup batch terakhir tepat di iterasi ke-5000 sehingga penugasan batch = [] menjadi pernyataan terakhir yang dievaluasi. Jumlah 5000 dari countDocuments menegaskan seluruh batch masuk.

Sekarang nyalakan profiler level 2, jalankan query pencarian judul, lalu segera matikan — semuanya dalam satu blok agar profil tidak pernah lupa dimatikan:

db.setProfilingLevel(2, { slowms: 100 })
db.buku_besar.find({ judul: "Buku Nomor 4999" }).itcount()
db.setProfilingLevel(0)

Output yang Dihasilkan:

{
  was: 0,
  slowms: 0,
  slowinprogms: Long('5000'),
  sampleRate: 1,
  ok: 1
}
1
{
  was: 2,
  slowms: 100,
  slowinprogms: Long('5000'),
  sampleRate: 1,
  ok: 1
}

Respons setProfilingLevel di atas dipadatkan dari metadata waktu replikasi ($clusterTime) seperti biasa. Angka 1 di tengah adalah hasil itcount() — satu document cocok. Satu kebiasaan membaca yang penting: respons setProfilingLevel melaporkan keadaan SEBELUM perintah diterapkan — itulah kenapa was dinamai demikian. Respons pertama menunjukkan was: 0, slowms: 0 (level 0 dengan slowms 0 — sisa dari sesi lain di server latihan ini; di server pembaca nilainya bisa 100), dan respons penutup menunjukkan was: 2 yang menegaskan level 2 memang sempat aktif dengan slowms: 100 yang barusan kita pasang.

Membaca Jejak di system.profile #

Operasi yang barusan berjalan kini punya catatan permanen. Kita ambil entri query terakhir untuk collection kita, dengan projection yang hanya memuat field diagnosis:

db.system.profile.find(
  { op: "query", ns: "latihan_trouble.buku_besar" },
  { millis: 1, planSummary: 1, docsExamined: 1, nreturned: 1, "command.filter": 1 }
).sort({ ts: -1 }).limit(1)

Output yang Dihasilkan:

[
  {
    command: { filter: { judul: 'Buku Nomor 4999' } },
    docsExamined: 5000,
    nreturned: 1,
    millis: 1,
    planSummary: 'COLLSCAN'
  }
]

Dua angka itu inti diagnosisnya: docsExamined: 5000 — server memeriksa seluruh collection — untuk nreturned: 1 document yang benar-benar dikirim. Rasio 5000:1 pada lima ribu document masih terasa cepat (millis satuannya milidetik), tetapi rasio yang sama pada lima juta document adalah cerita lain; polanya identik, hanya skalanya yang berbeda. planSummary: 'COLLSCAN' menegaskan penyebabnya: collection scan, query yang filter-nya tidak didukung index.

Explain: Mengukur Sebelum Menyembuhkan #

Sebelum memperbaiki, ukur dulu dengan explain agar perbaikan nanti punya pembanding. Kita ekstrak field biaya utamanya agar ringkas:

const st = db.buku_besar.find({ judul: "Buku Nomor 4999" }).explain("executionStats").executionStats
({ stage: st.executionStages.stage, docsExamined: st.totalDocsExamined, nReturned: st.nReturned, millis: st.executionTimeMillis })

Output yang Dihasilkan:

{ stage: 'COLLSCAN', docsExamined: 5000, nReturned: 1, millis: 1 }

Hasilnya konsisten dengan catatan profiler — stage: 'COLLSCAN', 5000 document diperiksa. Penafsiran mendalam tiap field (seperti executionStages bertingkat dan works) dibahas di Chapter Explain Execution Stats; untuk triage, empat field ini sudah cukup untuk memutuskan tindakan.

Perbaiki dengan Index, Bukti dengan Explain Kedua #

Field filter kita adalah judul, jadi kandidat perbaikannya jelas: index pada field itu. Setelah dibuat, jalankan explain yang sama persis:

db.buku_besar.createIndex({ judul: 1 })
const st = db.buku_besar.find({ judul: "Buku Nomor 4999" }).explain("executionStats").executionStats
({ inputStage: st.executionStages.inputStage.stage, keysExamined: st.totalKeysExamined, docsExamined: st.totalDocsExamined, nReturned: st.nReturned })

Output yang Dihasilkan:

judul_1

{
  inputStage: 'IXSCAN',
  keysExamined: 1,
  docsExamined: 1,
  nReturned: 1
}

Rencana eksekusi berubah total: tahap IXSCAN membaca satu kunci index (keysExamined: 1), lalu FETCH mengambil satu document (docsExamined: 1) — dari 5000 pemeriksaan menjadi satu. Inilah bukti perbaikan yang bisa ditunjukkan, bukan sekadar kesan “sepertinya lebih cepat”. Tutup sesi dengan memastikan profiler memang kembali mati:

db.getProfilingStatus()

Output yang Dihasilkan:

{
  was: 0,
  slowms: 100,
  slowinprogms: Long('5000'),
  sampleRate: 1,
  ok: 1
}

Sama seperti respons setProfilingLevel, keluaran getProfilingStatus di atas dipadatkan dari metadata waktu replikasi. Field was: 0 pada getProfilingStatus menunjukkan level SAAT INI (penamaan warisan sejarah): profiler sudah mati kembali, dan slowms: 100 tersimpan untuk sesi diagnosis berikutnya.

Rangkuman #

• Alur triage satu siklus: profiler menangkap, system.profile mengidentifikasi, explain mengukur, index memperbaiki, explain kedua membuktikan.
• Pasangan docsExamined versus nreturned adalah indikator biaya tercepat; COLLSCAN adalah temuan yang paling sering.
• Profiler level 2 hanya untuk jendela pendek — nyalakan, pancing, matikan dalam satu sesi.
• Perbaikan yang sah selalu bisa ditunjukkan dengan angka sebelum-sesudah, bukan dengan perasaan.