Analisis Slow Query

Aplikasi terasa lambat, tetapi dari ratusan query yang berjalan tiap menit, mana yang benar-benar bersalah? Menebak dari nama fungsi saja jarang tepat — penjahatnya sering query yang paling tidak dicurigai. Database profiler MongoDB merekam setiap operasi beserta waktunya ke collection system.profile, lengkap dengan ringkasan rencana eksekusinya. Chapter ini menjalankan siklus lengkapnya di lingkungan latihan: aktifkan profiler, pancing query, baca catatannya, lalu matikan kembali — plus batasan penting kenapa profiler tidak boleh menyala terus-menerus.

Peta materi Chapter ini:

• Tiga level profiler dan peran slowms.
• Siklus nyata: level 2 → query → baca system.profile → level 0.
• Field kunci entri profil: ns, command, millis, planSummary.
• Ringkasan agregat untuk menemukan pola query boros.

Tiga Level Profiler #

Profiler diaktifkan per database lewat db.setProfilingLevel(). Tiga levelnya:

Ambang slowms berlaku lintas level: pada level 0 ia menentukan operasi apa yang ditulis ke berkas log mongod, pada level 1 ia menentukan operasi apa yang masuk system.profile. Nilai defaultnya 100 milidetik — cukup longgar untuk aplikasi web umum, dan lazimnya diturunkan bertahap (misalnya ke 20) saat kita ingin menangkap lebih banyak.

Siklus Nyata: Aktifkan, Panji, Matikan #

Siapkan data transaksi ringkas:

use latihan_perf
db.dropDatabase()
db.penjualan.insertMany([
  { _id: 1, waktu: ISODate("2026-03-02T09:15:00Z"), judul_buku: "Laut Bercerita", jumlah: 1, harga_total: 98000, kota: "Jakarta", channel: "toko" },
  { _id: 2, waktu: ISODate("2026-03-02T11:40:00Z"), judul_buku: "Bumi", jumlah: 2, harga_total: 178000, kota: "Bandung", channel: "online" },
  { _id: 3, waktu: ISODate("2026-03-03T10:05:00Z"), judul_buku: "Filosofi Teras", jumlah: 1, harga_total: 89000, kota: "Jakarta", channel: "online" },
  { _id: 4, waktu: ISODate("2026-03-03T14:30:00Z"), judul_buku: "Atomic Habits", jumlah: 3, harga_total: 345000, kota: "Surabaya", channel: "toko" }
])

Output yang Dihasilkan:

switched to db latihan_perf
{ ok: 1, dropped: 'latihan_perf' }
{ acknowledged: true, insertedIds: { '0': 1, '1': 2, '2': 3, '3': 4 } }

Kita memakai dropDatabase() (bukan db.penjualan.drop()) agar system.profile yang mungkin berisi catatan sesi lama ikut terhapus — begitu profiler menyala, collection itu dibuat ulang kosong. Nyalakan profiler level 2, jalankan dua query tanpa index, lalu matikan — semuanya dalam satu blok agar profiler tidak pernah lupa dimatikan:

db.setProfilingLevel(2, { slowms: 100 })
db.penjualan.find({ kota: "Jakarta" }).itcount()
db.penjualan.find({ channel: "online" }).sort({ harga_total: -1 }).itcount()
db.setProfilingLevel(0)

Output yang Dihasilkan:

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

Respons setProfilingLevel dipadatkan dari metadata waktu replikasi seperti biasa. Field was menunjukkan level sebelum perintah dijalankan — was: 2 pada perintah kedua menegaskan level 2 memang sempat aktif. Angka 2 dan 2 di tengah output adalah hasil itcount() — kedua query berjalan dan kini tercatat di system.profile.

Membaca Catatan system.profile #

Setiap operasi yang diprofil menjadi satu document. Kita baca dua entri pertama dengan projection yang memilih field-field diagnosis:

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

Output yang Dihasilkan:

[
  {
    op: 'query',
    ns: 'latihan_perf.penjualan',
    command: { filter: { kota: 'Jakarta' } },
    keysExamined: 0,
    docsExamined: 4,
    nreturned: 2,
    millis: 0,
    planSummary: 'COLLSCAN'
  },
  {
    op: 'query',
    ns: 'latihan_perf.penjualan',
    command: { filter: { channel: 'online' }, sort: { harga_total: -1 } },
    keysExamined: 0,
    docsExamined: 4,
    nreturned: 2,
    millis: 0,
    planSummary: 'COLLSCAN'
  }
]

Entri profil pada dasarnya adalah executionStats yang kita kenal dari Chapter Explain Execution Stats, dibungkus konteks operasi. Field yang paling sering dipakai:

Dua entri di atas sama-sama menunjukkan planSummary: 'COLLSCAN' dengan docsExamined: 4 — pada empat document memang tidak terasa, tetapi pola yang sama pada empat juta document adalah temuan klasik dari profiler: query yang filter-nya tidak didukung index.

Untuk traffic nyata, membaca entri satu per satu tidak praktis. Agregasi menjawab pertanyaan “pola rencana apa yang paling sering muncul”:

db.system.profile.aggregate([
  { $group: { _id: "$planSummary", jumlah: { $sum: 1 }, rataMillis: { $avg: "$millis" } } },
  { $sort: { jumlah: -1 } }
])

Output yang Dihasilkan:

[ { _id: 'COLLSCAN', jumlah: 2, rataMillis: 0 } ]

Grup berdasar planSummary langsung menonjolkan COLLSCAN sebagai pola dominan; variasi lain yang layak dicoba adalah mengelompokkan berdasar "command.filter" untuk melihat filter mana yang paling mahal, atau memfilter millis: { $gte: 20 } bila profiler dijalankan di level 2 dengan slowms rendah.

Terakhir, pastikan profiler memang kembali mati — kebiasaan penutup yang sebaiknya menjadi refleks:

db.getProfilingStatus()

Output yang Dihasilkan:

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

was: 0 menegaskan profiler kembali mati dan slowms tetap tersimpan di 100 — siap dipakai kapan pun kita butuh jendela diagnosis berikutnya.

Rangkuman #

• Profiler punya tiga level: 0 (mati, slowms hanya mengatur log), 1 (hanya operasi di atas slowms), 2 (semua operasi).
• Siklus diagnosis yang aman: aktifkan level 2 → jalankan skenario terduga → baca system.profile → kembalikan level 0, semuanya dalam satu sesi singkat.
• Entri profil memuat ns, command, millis, planSummary, plus keysExamined/docsExamined/nreturned — gabungan identitas, durasi, dan biaya.
• Agregasi atas system.profile (grup per planSummary atau per filter) mengubah tumpukan catatan menjadi daftar tersangka yang terurut.