Profil prestasi aplikasi CFML: cari leher botol sebenar

Profil prestasi aplikasi CFML: cari leher botol sebenar

Profil prestasi ialah kerja mengukur sebelum menala, dan ia menyelamatkan anda daripada membuang masa membetulkan perkara yang sebenarnya laju. Aplikasi Lucee CFML yang perlahan hampir selalu ada satu punca utama, contohnya satu query yang lambat atau satu gelung yang tersalah tulis, dan cara mencarinya bukan dengan meneka, tetapi dengan mengukur. Artikel ini menunjukkan cara mengukur masa dengan getTickCount, kenapa satu ukuran tidak mencukupi, cara membaca metrik enjin, dan kenapa thread dump memberi jawapan yang tekaan tidak dapat beri.

Ukur masa dengan getTickCount

getTickCount() memulangkan masa semasa dalam milisaat. Bila anda memanggilnya sebelum dan selepas satu blok kerja, beza antara dua nilai itu ialah tempoh sebenar blok itu. Inilah alat profil paling asas dan paling berguna, kerana ia tidak memerlukan apa-apa pemasangan dan berjalan pada setiap templat CFML.

Contoh ini mengukur dua perkara berasingan: masa yang diambil oleh satu query, dan masa yang diambil oleh satu gelung yang membaca hasilnya:

<cfset mula = getTickCount()>

<cfquery name="senarai" datasource="kedai">
    SELECT id, nama, harga FROM produk ORDER BY id LIMIT 50
</cfquery>
<cfset selepasQuery = getTickCount()>

<cfset jumlah = 0>
<cfloop query="senarai">
    <cfset jumlah = jumlah + senarai.harga>
</cfloop>
<cfset tamat = getTickCount()>

<cfset masaQuery = selepasQuery - mula>
<cfset masaGelung = tamat - selepasQuery>

<cfoutput>
rekod=#senarai.recordCount#;query_ms=#masaQuery#;gelung_ms=#masaGelung#;jumlah=#numberFormat(jumlah, "0.00")#
</cfoutput>

Mengasingkan query daripada gelung ialah langkah pertama yang penting. Kalau query mengambil 200 milisaat dan gelung mengambil 2 milisaat, menala gelung itu sia-sia, leher botol sebenar berada di pangkalan data. Ukur setiap blok secara berasingan, bukan keseluruhan halaman sekali gus, kerana halaman yang perlahan hampir selalu perlahan kerana satu bahagian sahaja.

Satu ukuran tidak cukup: baca p50 dan p95

Masa satu permintaan tidak memberitahu apa-apa tentang aplikasi anda secara keseluruhan. Query yang mengambil 2 milisaat pada percubaan pertama mungkin mengambil 400 milisaat pada percubaan kesepuluh, kerana cache JVM belum panas, sambungan pangkalan data perlu dibuka, atau pemacu baru sahaja memuatkan kelas. Satu ukuran hanyalah titik rawak dalam julat yang luas.

Untuk melihat bentuk sebenar, jalankan kerja yang sama berkali-kali, kumpulkan semua masa, susun mengikut tertib, dan baca persentil. p50 ialah median, iaitu nilai tengah yang dirasai kebanyakan pengguna, manakala p95 ialah nilai yang lebih baik daripada 95 peratus percubaan. Beza besar antara p50 dan p95 menandakan ekor yang tidak stabil.

<cfset masa = []>
<cfset ulangan = 25>

<cfloop from="1" to="#ulangan#" index="i">
    <cfset mula = getTickCount()>
    <cfquery name="q" datasource="kedai">
        SELECT id, nama, harga FROM produk WHERE harga > 0 LIMIT 10
    </cfquery>
    <cfset arrayAppend(masa, getTickCount() - mula)>
</cfloop>

<cfset arraySort(masa, "numeric", "asc")>
<cfset p50 = masa[int(ulangan * 0.5)]>
<cfset p95 = masa[int(ulangan * 0.95)]>

<cfoutput>
ulangan=#ulangan#;min_ms=#masa[1]#;p50_ms=#p50#;p95_ms=#p95#;maks_ms=#masa[ulangan]#
</cfoutput>

Ini masih ukuran dalam satu proses, bukan ujian beban sebenar. Untuk melihat bagaimana aplikasi berkelakuan apabila berpuluh-puluh permintaan tiba serentak, anda perlu alat beban dan endpoint yang berasingan, seperti yang diterangkan dalam panduan ujian beban CFML. Di sini persentil masih berguna sebagai langkah pertama sebelum anda membawa alat luar.

Jadual di bawah merumuskan tahap ukuran dan bila setiap satu sesuai:

Baca metrik Lucee

Lucee mendedahkan metrik enjin terus daripada templat, tanpa sebarang alat luar. Dua yang paling kerap anda perlukan ialah server.lucee.version, yang memulangkan versi enjin yang sedang berjalan, dan getMemoryUsage(), yang memulangkan senarai kolam memori JVM. Bersama objek Runtime Java, anda boleh membaca heap yang terpakai dan had maksimumnya:

<cfset rt = createObject("java", "java.lang.Runtime").getRuntime()>
<cfset kolam = getMemoryUsage()>

<cfoutput>
enjin=#server.lucee.version#
heap_terpakai_mb=#numberFormat((rt.totalMemory() - rt.freeMemory()) / 1048576, "0.0")#
heap_maks_mb=#numberFormat(rt.maxMemory() / 1048576, "0.0")#
kolam_memori=#kolam.recordCount#
</cfoutput>

Pada rig ujian artikel ini, blok itu memulangkan enjin 7.1.1.17-RC dengan kira-kira 67 MB heap terpakai daripada maksimum 495 MB, dan 8 kolam memori. Pantau heap yang naik tanpa turun selepas permintaan selesai, itu tanda kebocoran. Apabila heap terlalu kecil, JVM melakukan kutipan sampah dengan kerap dan permintaan tersekat, dan di situlah panduan menala JVM menerangkan cara menetapkan saiz heap dan utas dengan betul. Metrik ini juga berpasangan dengan caching dan prestasi untuk mengurangkan kerja yang tidak perlu sebelum anda menambah sumber.

Query perlahan melalui log

Query ialah leher botol paling lazim dalam aplikasi CFML, jadi profil yang baik mesti menangkap query yang perlahan secara automatik dan menulisnya ke log. Daripada menyemak setiap query dengan tangan, tetapkan satu had masa, dan log hanya query yang melepasinya:

<cfset had = 200>
<cfset mula = getTickCount()>

<cfquery name="q" datasource="kedai" result="meta">
    SELECT id, nama, harga FROM produk ORDER BY harga DESC LIMIT 20
</cfquery>
<cfset masaMs = getTickCount() - mula>

<cfif masaMs GT had>
    <cflog file="query-perlahan" type="warning" text="Query produk ambil #masaMs# ms, rekod #q.recordCount#">
</cfif>

<cfoutput>masa_ms=#masaMs#;had_ms=#had#;executionTime_ms=#meta.executionTime#</cfoutput>

Perhatikan GT dan bukan > dalam <cfif>: dalam sintaks tag CFML, aksara > menutup tag, jadi perbandingan lebih besar mesti ditulis sebagai GT. result="meta" pula menyimpan masa sebenar yang dilaporkan pemacu JDBC dalam meta.executionTime, dan ia boleh berbeza sedikit daripada getTickCount kerana getTickCount turut mengira masa membuka sambungan.

Log query perlahan ini paling berguna apabila dihidupkan secara kekal dalam pengeluaran, supaya anda boleh melihat corak dari semasa ke semasa. Untuk membaca log itu dan menyediakan amaran, rujuk panduan log dan pemantauan. Jika query perlahan itu berpunca daripada sambungan pangkalan data yang habis atau salah konfigurasi pemacu, panduan sambungan MySQL membincangkan kolam sambungan dan tetapan yang perlu disemak.

Thread dump lebih berguna daripada meneka

Apabila aplikasi gantung atau permintaan tersekat lama, godaan untuk meneka punca sangat kuat, contohnya "mungkin pangkalan data lembap" atau "mungkin ada gelung tak terhingga". Tekaan membuang masa kerana setiap tekaan mesti diuji, dan tekaan yang salah menghantar anda ke arah yang salah. Thread dump ialah gambar segera semua utas JVM, dan ia memberitahu anda dengan tepat apa yang setiap utas lakukan pada saat itu, sama ada ia sedang berjalan, menunggu kunci, atau tersekat menunggu sambungan pangkalan data.

Satu thread dump yang diambil semasa permintaan tersekat hampir selalu mendedahkan punca sebenar dalam beberapa saat: utas yang menunggu pada soket pangkalan data, utas yang terkunci pada objek yang sama, atau utas yang sibuk dalam gelung. Ini jawapan langsung, bukan hipotesis. Lucee juga menyediakan alat pentadbiran untuk memeriksa utas yang sedang berjalan, tetapi apabila anda mahu bukti mentah daripada JVM itu sendiri, gunakan arahan ini:

# TIDAK-DIUJI: arahan ini memerlukan JDK dan proses JVM yang hidup di luar rig ujian.
# Ambil thread dump semasa permintaan tersekat untuk lihat utas mana yang menunggu:
jstack <pid-java> > thread-dump.txt

# Atau gunakan VisualVM untuk lihat utas secara langsung dan masa CPU setiap satu:
jvisualvm

Untuk membaca thread dump yang anda ambil, dan memahami apa yang dimaksudkan dengan utas yang tersekat berbanding yang menunggu, baca panduan thread dump dan heap dump. Gabungkan thread dump dengan ukuran masa di atas dan anda mempunyai gambaran penuh: ukuran memberitahu anda bahagian mana yang perlahan, dan thread dump memberitahu anda kenapa.

Soalan Lazim

Adakah getTickCount cukup untuk profil prestasi penuh?

Tidak, ia titik permulaan. getTickCount menunjukkan masa setiap blok, tetapi ia tidak menunjukkan persentil, memori, atau keadaan utas. Gunakannya dahulu untuk mencari blok yang perlahan, kemudian baca p50 dan p95, metrik enjin, dan thread dump untuk memahami puncanya.

Kenapa purata masa tidak boleh dipercayai?

Purata menyembunyikan ekor. Satu query yang mengambil 5 milisaat pada 19 percubaan dan 500 milisaat pada satu percubaan mempunyai purata rendah tetapi p95 yang tinggi, dan pengguna yang terkena percubaan 500 milisaat itulah yang mengadu aplikasi perlahan. Persentil mendedahkan ketidakstabilan ini.

Bila saya perlu mengambil thread dump?

Ambil thread dump apabila permintaan gantung atau tersekat lama, bukan semasa aplikasi berjalan lancar. Thread dump yang diambil pada saat tepat itulah yang menunjukkan utas mana yang menunggu, dan ia hampir selalu mendedahkan punca sebenar.

Adakah menambah had log query memperlahankan aplikasi?

Log itu sendiri ringan, kerana ia hanya menulis satu baris apabila query melepasi had. Kos getTickCount dan perbandingan hampir tiada. Tetapi jangan tetapkan had terlalu rendah sehingga setiap query dilog, kerana log yang banjir sukar dibaca dan menambah kerja tulis.

Bolehkah saya membaca thread dump terus daripada Lucee tanpa jstack?

Ya, pentadbir Lucee menyediakan pemeriksaan utas dalam halaman pentadbiran, dan ia berguna untuk semakan pantas. Tetapi jstack memberi bukti mentah daripada JVM dan berfungsi walaupun aplikasi tidak dapat dibuka langsung, jadi kedua-duanya patut diketahui.