PostgreSQL pg_stat_activity menunjukkan COMMIT

11

Kami baru-baru ini mengganti server database kami dengan mesin yang ditingkatkan dengan CPU 4 x quad core dan ram 32Gb. Kami juga menggunakan kembali kotak lama kami untuk berfungsi sebagai budak dengan replikasi streaming. Kedua kotak menjalankan CentOS 6.3 dan PostgreSQL 9.2. Postgres adalah satu-satunya hal yang berjalan di setiap kotak.

Konfigurasi ini telah berlangsung sekitar satu bulan atau lebih, ketika tiba-tiba kami mulai mengalami beberapa masalah ketika lalu lintas mulai meningkat. Apa yang sudah mulai kita lihat adalah beban CPU yang sangat tinggi di waktu (atas menunjukkan rata-rata beban 270), dan ketika kita bisa melihat pg_stat_activitykita akan melihat sebagian besar koneksi kita berada dalam COMMITkeadaan. Ketika dibiarkan sendiri, ini akhirnya akan selesai dan sistem akan menjadi responsif dengan koneksi menjadi IDLE. Kami telah mencoba menonaktifkan replikasi untuk melihat apakah itu masalah, tetapi masalahnya masih ada.

Kami telah mencoba mendiagnosis apa yang terjadi, dan sedikit hilang. Output dari menjalankan perfmenunjukkan sesuatu yang mirip di bawah ini, dan saya tidak tahu apa yang 0x347ba9diwakilinya.

+  41.40%       48154  postmaster  0x347ba9         f 0x347ba9                                   ◆
+   9.55%       10956  postmaster  0x2dc820         f set_config_option                          ▒
+   8.64%        9946  postmaster  0x5a3d4          f writeListPage     
+   5.75%        6609  postmaster  0x5a2b0          f ginHeapTupleFastCollect                    ▒
+   2.68%        3084  postmaster  0x192483         f build_implied_join_equality                ▒
+   2.61%        2990  postmaster  0x187a55         f build_paths_for_OR                         ▒
+   1.86%        2131  postmaster  0x794aa          f get_collation_oid                          ▒
+   1.56%        1822  postmaster  0x5a67e          f ginHeapTupleFastInsert                     ▒
+   1.53%        1766  postmaster  0x1929bc         f distribute_qual_to_rels                    ▒
+   1.33%        1558  postmaster  0x249671         f cmp_numerics

Tak satu pun dari pertanyaan yang dilakukan oleh aplikasi sangat kompleks, dengan menjelaskan rencana mengambil paling banyak 1 detik (kebanyakan lebih cepat). Selain itu, sementara ini terjadi ketika lalu lintas mulai mengambil, kita tidak berbicara tentang beban lalu lintas yang sangat besar (Mesin lama dulu dapat menanganinya dengan mudah).

Pada titik ini saya agak bingung tentang apa yang harus dicoba selanjutnya. Bantuan atau saran apa pun akan dihargai. Jika ada informasi tambahan yang akan membantu, tanyakan saja dan saya dapat mengubah pertanyaan.

Konfigurasi Disk:

  • Perc 6i RAID Controller
  • Drive SAS 5 x 146GB 15K
  • Dikonfigurasi sebagai 2x146GB RAID-1 untuk WAL dan 3x146GB RAID-5 untuk Sistem dan Data

Memperbarui:

Di bawah ini adalah output VMStat ketika sistem berfungsi normal dan ketika CPU menyala. Ketika ada masalah, interupsi tampaknya meroket.

Selama operasi normal:

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ ---timestamp---
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 18938590 303763 21947154    0    0    28    52 7466 12649  2  1 97  0  0   2013-01-14 16:03:25 EST
 0  0      0 18938396 303763 21947154    0    0     0    19 7107 12679  2  0 98  0  0   2013-01-14 16:03:35 EST
 1  0      0 18938904 303763 21947162    0    0     0    54 7042 12708  1  1 99  0  0   2013-01-14 16:03:45 EST
 1  0      0 18938520 303763 21947260    0    0    33    66 7120 12738  1  1 99  0  0   2013-01-14 16:03:55 EST

Saat penggunaan CPU tinggi:

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ ---timestamp---
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
343 0      0 32680468 226279 11339612    0    0     0   214 26692 12225 80  20  0  0  0   2013-01-11 16:45:53 EST
374 1      0 32673764 226291 11340345    0    0     0    77 54893 11572 80  20  0  0  0   2013-01-11 16:46:03 EST
383 0      0 32616620 226304 11340956    0    0     0   102 55540 12922 82  18  0  0  0   2013-01-11 16:46:13 EST
315 0      0 32602038 226320 11341378    0    0     0    79 54539 12441 82  18  0  0  0   2013-01-11 16:46:23 EST
postgresql jcern
sumber
Jenis disk apa yang dimiliki kotak baru? Apakah ini terjadi pada kedua node atau hanya satu dari mereka?
Trygve Laugstøl
@trygvis - Saya memperbarui pertanyaan dengan spesifikasi disk. Masalahnya terjadi pada node Master. Saya belum mencoba mempromosikan Budak dan mengarahkan lalu lintas ke sana, jadi saya tidak yakin apakah ini masalah di sana juga dalam kondisi yang sama. Sebagai seorang budak, mesin tampaknya tidak mengalami masalah apa pun.
jcern
2
Pertimbangkan untuk menggunakan perfalat ini untuk melakukan beberapa profil seluruh sistem dan beberapa profil PostgreSQL. Lihat di mana penggunaan CPU terjadi. BTW, format ke-2 Anda vmstathancur berantakan, dan kolom ke-1 tidak selaras sehingga sulit dibaca. Uji untuk melihat apakah menambahkan sesuatu commit_delaymeningkatkan. Periksa apakah pengontrol RAID Anda memiliki cache write-back yang didukung baterai dan jika tidak, dapatkan satu. Apakah banyak waktu dihabiskan iowait? Ini tampaknya penggunaan CPU dalam beberapa pelaporan, tetapi sebenarnya tidak.
Craig Ringer
@CraigRinger controller memang memiliki cache tulis yang didukung baterai, dan yang saat ini diaktifkan. Menunggu dari iostat tetap di tunggal hingga dua digit. Kami akan terus mencoba profil lebih lanjut dengan perf. Saya juga memperbaiki format VMStat kedua, terima kasih telah menunjukkannya.
jcern

Jawaban:

11

Setelah diagnosa lebih lanjut dan beberapa Googling, kami menemukan artikel ini yang menggambarkan banyak gejala yang sama yang kami alami. Akar penyebab masalah mereka (dan dari apa yang dapat kami sampaikan, masalah kami juga) terkait dengan Transparent Huge Pagesimplementasi.

Setelah menonaktifkan Transparent Huge Pagesdengan perintah ini:

echo never > /sys/kernel/mm/redhat_transparent_hugepage/enabled

Masalahnya tampaknya telah diselesaikan. Kami telah menjalankan beban kerja yang meningkat selama dua minggu terakhir dan masalah ini belum muncul kembali. Konteks dan interupsi sistem secara konsisten 1/10 dari yang sebelumnya dan rata-rata waktu sistem juga berkurang.

Tidak yakin apakah ini solusi untuk semua orang, tetapi saya mempostingnya di sini sebagai kemungkinan penyebabnya jika itu dapat membantu orang lain menyelesaikan masalah serupa.

jcern
sumber