Case 10 · Oracle Performance · AWR Compare

ระบบ CRM ช้า เพราะ Transaction กำลังรอ Lock กันเอง

ผู้ใช้ CRM ต้องรอการตอบสนองนานขึ้น ทีมจึงเปิด AWR (รายงาน Performance ที่ Oracle เก็บจากการทำงานจริงของระบบ) และพบว่าเวลาส่วนใหญ่ไม่ได้หมดไปกับการคำนวณ แต่หมดไปกับการรอ Lock ที่ Oracle เรียกว่า enq: TM - contention

Oracle Database AWR Compare Period Lock Contention ระบบ CRM ปกปิดชื่อระบบและ Object
เรื่องราวของเหตุการณ์ · Case Story

เมื่อ CRM ช้า ทั้งที่ CPU ไม่ได้ทำงานหนักขึ้น

ผู้ใช้ระบบ CRM เริ่มรู้สึกว่าการทำงานช้าลงและต้องรอการตอบสนองนานกว่าปกติ ทีมจึงนำ AWR ของช่วงปกติมาเปรียบเทียบกับช่วงที่เกิดอาการ ก่อนอ่านตัวเลขเหล่านี้ มีหลักสำคัญเพียงข้อเดียวที่ช่วยให้เห็นภาพทั้งหมด:

DB Time = DB CPU + Wait Time (Non-idle)

DB Time (เวลารวมของงานฐานข้อมูล) จึงประกอบด้วยเวลาที่ Oracle กำลังประมวลผลบน CPU และเวลาที่งานต้องหยุดรอสิ่งอื่น

หากนึกว่า DB Time มี 100 ส่วน บางส่วนคือ DB CPU (ช่วงที่ฐานข้อมูลกำลังประมวลผลจริง) ส่วนที่เหลือคือ Wait Time (ช่วงที่งานยังไม่เสร็จเพราะกำลังรอ เช่น Disk, Network หรือ Lock) ตัวเลขนี้เป็นเวลารวมของหลาย Session จึงไม่ใช่เวลาบนนาฬิกา และ CPU time ใน AWR ก็ไม่ใช่เปอร์เซ็นต์ CPU Utilization ของเครื่อง Server

ในช่วงปกติ CPU time คิดเป็น 72.60% ของ DB Time หรือพูดง่าย ๆ ว่าเวลาส่วนใหญ่ถูกใช้ไปกับการประมวลผลงาน แต่ในช่วงที่ CRM ช้า CPU time กลับเหลือ 27.02% ขณะที่ enq: TM - contention (การรอ Lock ที่เกี่ยวข้องกับ Table หรือ Object) เพิ่มขึ้นเป็น 61.98% ของ DB Time

ภาพจึงเหมือนช่องบริการที่พนักงานยังทำงานได้ แต่เอกสารสำคัญถูกอีกคนถือไว้ งานถัดไปจึงต้องต่อคิวรอ การเพิ่มพนักงานหรือเพิ่ม CPU ไม่ได้ทำให้เอกสารถูกส่งต่อเร็วขึ้น ทีมต้องหาให้พบว่าใครถือ Lock อยู่และงานใดกำลังรอ

จุดที่เปลี่ยนทิศทางการวิเคราะห์ ตัวเลข 61.98% ทำให้ทีมเลิกมองหาวิธีเพิ่มกำลังประมวลผล แล้วหันไปตามรอยว่า Session ใดกำลัง Block งานของใคร เกิดกับ Object ใด และมี SQL ชุดไหนเกี่ยวข้อง

อยากเข้าใจศัพท์ให้ลึกขึ้น?

อ่านต่อได้ที่ AWR คืออะไร, DB Time, DB CPU และ Wait Time และ Wait Event บอกอะไรเรา

เส้นทางการวิเคราะห์ · The Investigation

จาก Wait Event ไปถึง Transaction ที่กำลังรอกัน

บทที่ 1 · อ่านสิ่งที่เปลี่ยนไป

AWR ไม่ได้บอกแค่ว่าระบบช้า แต่บอกว่าระบบเสียเวลาไปกับอะไร

ทีมเปรียบเทียบช่วงปกติกับช่วงที่เกิดอาการ แทนการอ่านรายงานเพียงช่วงเดียว การเปลี่ยนจาก CPU time ไปเป็น enq: TM - contention ทำให้เห็นว่าคอขวดได้ย้ายจากการประมวลผลไปอยู่ที่การรอ DML Enqueue (กลไก Lock ที่ Oracle ใช้ควบคุมการเปลี่ยนข้อมูล)

บทที่ 2 · ตามรอยผู้ที่กำลังรอ

enq: TM - contention หมายความว่าอะไร

Transaction คือชุดคำสั่งที่ต้องทำให้เสร็จเป็นหน่วยเดียว ส่วน Lock คือกลไกที่ป้องกันไม่ให้หลาย Transaction เปลี่ยนข้อมูลส่วนเดียวกันจนขัดแย้งกัน หาก Transaction หนึ่งถือ Lock ไว้ อีก Transaction ที่ต้องใช้ Object เดียวกันอาจต้องรอ

TM เป็น DML Enqueue ที่เกี่ยวข้องกับ Table หรือ Object เมื่อ AWR แสดง enq: TM - contention สูง จึงรู้ว่ามีการรอ Lock ประเภทนี้มาก แต่ยังไม่รู้ว่าใครถือ Lock หรือ Table ใดเกี่ยวข้อง

ทีมจึงไล่ต่อไปยัง Blocking Session (Session ที่ถือ Lock และทำให้งานอื่นต้องรอ), Waiting Session (Session ที่ยังทำงานต่อไม่ได้), Enqueue Mode, Object และ SQL ในช่วงเวลาเดียวกัน แล้วตรวจ Foreign Key กับ Index เฉพาะโครงสร้างที่สัมพันธ์กับเหตุการณ์

บทที่ 3 · แยกปัญหาที่เกิดพร้อมกัน

log file sync ต้องถูกตรวจ แต่ไม่ควรกลบสาเหตุของ Lock

รายงานยังมี log file sync และ log file parallel write ทีมจึงแยกตรวจ Commit Frequency, LGWR Scheduling และ I/O Latency เพื่อให้การแก้ Redo กับการแก้ Lock Contention ไม่ถูกนำมาปะปนกัน

หลังดำเนินการ: เมื่อแก้จุดที่ทำให้ Transaction รอกัน การรอ Lock ลดลง และผู้ใช้กลับมาทำงานผ่าน CRM ได้คล่องขึ้น โดยไม่ต้องแก้ปัญหาด้วยการเพิ่ม Hardware เพียงอย่างเดียว
เบื้องหลังการแก้ · What We Did

ทีมเปลี่ยนสิ่งที่ AWR บอก ให้เป็นจุดที่ลงมือแก้ได้อย่างไร

แทนที่จะสร้าง Index ทุกจุดหรือเพิ่ม Hardware ทีมค่อย ๆ จำกัดวงจากระดับระบบลงไปถึง Transaction ที่เกี่ยวข้อง:

  1. ระบุ Blocking Session, Waiting Session, enqueue mode และ Object ที่เกี่ยวข้องในช่วงเวลาเดียวกับเหตุการณ์
  2. เชื่อม Object กับ SQL และลำดับ DML เพื่อดูว่าการรอเกิดจากธุรกรรมใด
  3. ตรวจ Foreign Key และ Index เฉพาะตารางที่หลักฐานชี้ถึง พร้อมตรวจผลกระทบต่อ DML และพื้นที่จัดเก็บ
  4. วิเคราะห์ log file sync ร่วมกับ commit frequency, LGWR scheduling, redo write latency และ log file parallel write
  5. ติดตาม Wait Profile และการตอบสนองของ CRM หลังเปลี่ยนแปลง เพื่อดูว่าการรอลดลงตรงจุดที่แก้

สิ่งที่ทีมไม่ได้ทำแบบเหมารวม: สร้าง Index ให้ Foreign Key ทุกตัว เพิ่มขนาด Redo Log เพียงเพราะพบ log file sync หรือเปิด Asynchronous Commit โดยไม่ประเมินผลต่อความถูกต้องของธุรกรรม

ห้องเทคนิค · For DBA/IT

เปิดดู AWR, Wait Event และเหตุผลทางเทคนิค

เนื้อหาส่วนนี้เก็บตัวเลขและศัพท์ Oracle ไว้ครบสำหรับ DBA/IT และการค้นหา แต่พับไว้เพื่อไม่ให้ขัดจังหวะเรื่องราวหลัก

ตัวเลขที่ทำให้ทิศทางการวิเคราะห์เปลี่ยน — AWR Compare Period

AWR (Automatic Workload Repository) คือข้อมูลสถิติ Performance ที่ Oracle เก็บตามช่วงเวลา รายงาน AWR ช่วยให้เปรียบเทียบได้ว่าฐานข้อมูลใช้เวลาไปกับ CPU, การรอ และงานประเภทใดบ้างในช่วงที่สนใจ

Metric/Event ช่วงเปรียบเทียบ A ช่วงเปรียบเทียบ B สถานะ
CPU time 72.60% 27.02% ยืนยันจาก AWR
enq: TM - contention ไม่อยู่ในรายการที่บันทึก 61.98% ยืนยันจาก AWR
log file sync 17.48% 5.71% ยืนยันจาก AWR
log file parallel write 10.55% 3.50% ยืนยันจาก AWR
DB Time, DB CPU และ Wait Time ต่างกันอย่างไร

DB Time คือเวลารวมที่ Foreground Session ใช้ในการเรียกฐานข้อมูล โดยคิดจาก DB CPU + Non-idle Wait Time และรวมเวลาของ Session ที่ทำงานพร้อมกัน จึงอาจมากกว่าเวลาจริงบนนาฬิกาได้

DB CPU คือเวลาที่ฐานข้อมูลใช้ CPU ประมวลผลงาน ส่วน Non-idle Wait Time คือเวลาที่งานต้องรอทรัพยากรหรือเหตุการณ์ที่มีผลต่อการทำงาน ไม่รวมการรอแบบ Idle ซึ่งไม่มีงานให้ทำ

ในตาราง Top Timed Events ของ AWR รายการ CPU time แสดงสัดส่วนเวลาประมวลผลต่อ DB Time ไม่ใช่ค่า CPU Utilization ของ Operating System

enq: TM - contention หมายความว่าอะไร

enq: TM - contention เป็นการรอ DML enqueue ที่เกี่ยวข้องกับ Table/Object การพบ Event นี้ใน AWR ยืนยันว่ามี lock contention แต่ AWR ส่วนนี้เพียงอย่างเดียว ยังไม่สามารถระบุ Object, lock mode, Blocking Session หรือเหตุผลที่ lock ถูกถือไว้นานได้

Foreign Key ที่ไม่มี Index เป็นหนึ่งในสาเหตุที่ควรตรวจเมื่อมี DML บน Parent Key แต่ไม่ควรถูกประกาศเป็น Root Cause จนกว่าจะเชื่อมโยง blocker, object และ constraint ได้

log file sync และ log file parallel write

เมื่อ session ทำ COMMIT การรอ log file sync ครอบคลุมเวลาที่รอให้ LGWR flush redo และตอบกลับ session ส่วน log file parallel write เป็นข้อมูลฝั่งการเขียน redo ของ LGWR จึงต้องวิเคราะห์ทั้งสอง Event ร่วมกับ commit rate, I/O latency และ CPU scheduling ของ LGWR

Redo size 67,926 bytes/second ไม่ได้พิสูจน์ว่า Redo Log เล็กเกินไป และขนาด Redo Log มีผลกับความถี่ของ log switch มากกว่าการแก้ทุกสาเหตุของ commit latency

Oracle Error, Wait Event และข้อมูลที่เผยแพร่

Wait Event คือชื่อที่ Oracle ใช้บันทึกว่า Session กำลังรออะไร เช่น รออ่านข้อมูล รอเขียน Redo หรือรอ Lock ชื่อ Event ช่วยชี้ทิศทาง แต่ยังต้องเชื่อมกับเวลา Session, Object และ SQL ก่อนสรุปสาเหตุ Case นี้เป็นปัญหา Oracle Wait Event enq: TM - contention ซึ่งวิเคราะห์จาก AWR, Blocking Session, Object และ SQL การค้นหาปัญหาประเภทนี้จึงควรใช้ชื่อ Wait Event ที่ตรงกับอาการ ส่วนรหัส ORA-xxxxx เหมาะกับ Incident ที่มี Oracle Error ระบุโดยตรง เช่น ORA-01653

ชื่อองค์กร ระบบ Schema, Table, Constraint, SQL และข้อมูลภายในถูกปกปิด ตัวเลขที่เผยแพร่จำกัดเฉพาะข้อมูลสรุปที่ใช้ทำความเข้าใจพฤติกรรมของระบบ

แหล่งข้อมูล · Sources

ที่มาของตัวเลขและคำอธิบาย Wait Event

  • หลักฐาน Case: AWR Compare Period และ Fact Sheet ที่จัดทำจากเอกสารต้นทางภายใน โดยไม่เผยแพร่ชื่อไฟล์หรือชื่อระบบ
  • การปกปิดข้อมูล: ไม่เผยแพร่ชื่อองค์กร ระบบ Hostname, Schema, Object, SQL หรือข้อมูลภายในของลูกค้า
  • DB Time และ CPU time: อ้างอิง Oracle Database Performance Tuning Guide: Time Model Statistics
  • คำอธิบาย Wait Event: อ้างอิงความหมายทั่วไปจาก Oracle Database Reference

ระบบของคุณช้า ทั้งที่ CPU หรือ Hardware ดูไม่น่าจะเป็นปัญหาหรือไม่?

enq: TM - contention เป็นเพียงหนึ่งในรูปแบบของการรอ ทีม VT Technology ช่วยเชื่อมอาการของผู้ใช้กับ AWR, Session, Object และ SQL เพื่อหาจุดที่ควรแก้จริง

ปรึกษาการวิเคราะห์ Oracle Performance