แชร์ประสบการณ์แก้ปัญหา Latch:cache buffer chain ( CPU 100% / Waiting sessions )

What is the Buffer Cache?
The buffer cache is an area of the Oracle shared memory (SGA) that Oracle keeps copies of
database block or data. When Oracle requests access to Oracle block, for any select statements,
Oracle looks in database buffer cache (memory) at first. If Oracle cannot find a specified data
block, Oracle will execute an OS read call for an Oracle block from the physical disk, containing
Oracle database file and copy such block to the designated database buffer cache.

There are two types of Oracle block read call:
•! LIO or logical I/O: Take place any time that Oracle requests access data block in
database buffer cache (memory).
•! PIO or physical I/O: Take place any time that Oracle executes OS read call from Oracle
database file (disk).

What is a latch?
Latch is a mechanism used to protect shared data in Oracle shared memory (SGA). A latch is a
type of lock which could be very quickly acquired and released. It is typically used to prevent
more than one process executing the same code at the same time.
A process acquired a latch when working with database buffer cache. It continues to hold latch
until finish its works. Other processes will have to wait for further execution with a latch that has
already been obtained by another process.

Latch: cache buffers chains
Oracle process needs to get a latch when searching for data block in the database buffer cache.
Since the database buffer cache is a chain of blocks, each of this chains is protected by latch
when needs to be scanned for searching. Contention in this latch can be caused by very
heavy access to a single block via logical read or LIO. Typically, from SQL statement that read
more buffer than they need to and multiple sessions are waiting to read the same block.
What causes latch contention?
If a required latch is busy, the process requesting CPU spin (a technique in which process trying
to acquire a lock while repeatedly checking if the lock is available) tries again and if still
unavailable, then spins again. If after this entire loop, the latch is still unavailable, the process
must yield the CPU and go to sleep. The sleep time is doubled in every subsequent sleep. This
causes a slowdown to occur and results in additional CPU usage, until a latch is available.

เราจึงสรุปได้ว่าปัญหาที่เกิดขึ้นมันเกิดจากการไป Access พื้นที่บน Memory ที่เดิมๆ Latch เดิมๆ ซ้ำๆ ถี่ๆ อาจจะเป็นไปได้ถึงระดับ centi ซึ่ง session ที่รอนั้นมันมีจำนวนมาก และกอด cpu usage ไว้ด้วยจนกว่าจะได้ทำจนเสร็จ การทำงานในลักษณะนี้จะเกิดจากการเขียนโปรแกรมประเภทที่ทำให้เกิดมีการวนลูป + กับรันถี่ๆ ที่ Block เดิมๆ Latch เดิมๆบน Buffer Cache นั่นเองครับ

ซึ่งเราสามารถดูได้นะครับว่า Block ไหน แต่เราจะไม่ดูไปถึงขนาดนั้นเพราะมันก็ไม่ได้ช่วยเราแก้ไขปัญหาได้ เราต้องหา Table นั้นครับที่มีการ Access บ่อยๆ คิวรี่ซ้ำๆ ถี่ๆครับ แล้วโยนไปให้ Developer แก้ไข โปรแกรม ซะ ถือว่าเราได้ข้อมูลที่มีมูลมากพอให้เค้าไปแก้ไขแล้ว

( ซึ่งในเคสของผมนั้นเกิดจาก Batch script รันถี่ แล้วเป็น script รันเป็น loop select อีก + Data บน Table ที่ไปวนลูปมีจำนวนมหาศาลเข้าไปอีก )

ตามหาสาเหตุของปัญหา

เคสที่ผมเจอนั้น มันเป็นปัญหามาจาก Waiting sessions event ที่ชื่อว่า ” Latch:cache buffer chain ” ซึ่งกว่าผมจะทราบว่ามันคืออะไรกันแน่ แล้วหาหลักฐานไปยืนยันกับทาง Developer ได้ ก็กินเวลายาวนานเลยทีเดียว ผมขอท้าวความปัญหาตั้งแต่ต้นเลยนะครับ เพื่อให้เห็นภาพชัดๆกันไปเลย ผมได้ทำการเก็บภาพตั้งแต่เจอปัญหา จนแก้ปัญหาได้เอาไว้หมดแล้ว

ก่อนอื่นต้องบอกสภาพแวดล้อมคร่าวๆของ Oracle Database server ของผมที่มีปัญหาก่อนว่าเป็น RAC ที่มีจำนวนโหนด 2 โหนดนะครับ

ภาพที่1. ภาพแรกนี้เป็น CPU และ session ของโหนด 1 ครับ ซึ่งสภาพนี่น่าเป็นห่วงมากๆ

ภาพที่2. ภาพนี้เป็น CPU และ session ของโหนด 2 ครับ ซึ่งสภาพนี่แหม่ชิวสุดๆ

      เนื่องจากตอนแรกที่ผมเห็นสภาพ DB ทั้งสองโหนดมีการทำงานไม่เท่ากันเลยคิดว่ามันน่าจะเป็นที่ Function ของ Load Balance Server นั้นทำงานไม่ถูกต้อง เพราะ Active sessions ของทั้งสอง Node มันไม่เท่ากันเอาซะเลย ( 150 / 30 ) จึงพ้อยไปที่ การแก้ไข Function ของ Load Balance นี้ก่อน
ซึ่งเมื่อตรวจสอบดูก็พบว่า Load Balance ที่ใช้งานอยุ่ตอนนี้มันเป็น Load Balance sessions นั่นคือ จำนวน session ของทั้งสองโหนดจะต้องเท่ากัน แต่เอ๊ะก็เราเห็น Active session มัน   ( 150 / 30 ) นี่นามันจะไปเท่ากันได้ยังไง นั่นเพราะเราลืมเจ้าพวก Inactive session นับรวมไปด้วยครับ ซึ่งจริงๆแล้วทั้ง 2 โหนดมันใกล้เคียงกันมาก
อ้าวแบบนี้ผมก็พอมีหวังแล้วสิ ถ้าแก้ไข Function นี้ให้มันเป็น Load Balance ด้วย CPU Usage ได้ มันก็น่าแบ่งๆงานกันทำคงไม่ถึงร้อยแล้ว  ไปแก้ Service function load balance กันเถอะ ( วิธีการทำเอาไว้ในจะเขียนบทความถัดไปนะครับ )

      และนี่คือภาพหลังจากที่เราแก้ไข Service function ให้เป็น Load balance by CPU ครับ ผ่างงงงงงงง

ภาพที่3. ภาพนี้เป็น CPU และ session หลังจากแก้ไขเป็น Load Balance by cpu usage.

      เห้ยยยยยยยย โอโหหนักหนากว่าเดิมเลยทีนี้ นั่นแสดงว่า ไอ่ตัวปัญหาเนี่ยมันไม่สามารถถูกกำจัดออกไปได้ด้วยการ แชร์ Load balance ครับ บอกเป็นนัยๆได้ว่ามันใช้ทรัพยากรณ์ของเครื่องที่มันไปทำงานหนักมาก ขอแถมภาพของ nmon ซักหน่อย

ภาพที่4. เป็นภาพจาก nmon file แสดง Cpu ก่อนหละหลังแก้ไข Load balance ครับ / ด้านบนเป็น node2 ด้านล่างเป็น node1 ครับ กราฟที่จะให้ดูคืออันบนครับ สังเกตว่าหลังจากเวลาที่เราปรับ Function Load Balance  CPU ก็แน่นิ่งอยุ่ที่ 100% ไปด้วยอีกครื่องทันที

เอ๋ สรุปว่า CPU มันทำงานหนักงานอะไรนะ คร่าวนี้ต้องมาลงลึงในส่วนรายละเอียดของ Session ต่างๆกันดูบ้าง ( ซึ่งเราไม่รู้ว่า CPU ทำไมถึงทำงานหนักขนาดนี้ มันรันงานหนักจริงๆ หรือมันทำอะไรกันแน่ )
ซึ่งเมื่อเราลอง Query session ต่างๆที่ Active ออกมาดูเราจะพบว่ามันมี session จำนวนมากเลยที่เดียว ผมตัดมาให้ดูบางส่วนนะครับ

ภาพที่5. ภาพนี้เป็น event session ณ ช่วงเวลาที่รันคิวรี่ ( Current time )

      จากภาพเราก็เห็น Wait class ที่เป็น User I/O อันนี้คือมัน read ข้อมูลครับ ส่วน Event ของ  Class นี้เอาไว้โอกาศหน้าจะมาเล่าให้ฟังนะครับ เมื่อมองๆไปเราก็จะเห็น Wait Class ที่เป็น Concurrency ครับ อันนี้เป็น Class ที่ค่อนข้างซีเรียสละ เพราะมันกระทบกับการทำงานของ Server แน่นอน (อืด) แล้วเราก็จะเห็น Event แปลกๆตัวนึงขึ้นมา Event ” Latch:cache buffer chain ” มันคืออะไรนะ  แต่มันมีคำว่า Cache Buffer เอ๋มันน่าจะเกี่ยวกับ Memory รึเปล่านะ
หากเราตรวจสอบ Query ของเจ้า Session ที่เราสงสัยนี้เราก็จะพบว่า ประเด็นของ Event นี้เกิดจากการกระทำที่ Table อะไร

>> MC_ONLINE_IF_HEADEER_LOG <<

ภาพที่6. Query ที่พบ ข้อมูลภายในเป็นข้อมูลที่ผมปรุงแต่งขึ้น เพื่อปกปิดข้อมูลที่อาจรั่วไหลของบริษัทของผมนะครับ

ซึ่งจากที่ผมดูทุก Session ที่มีการรอลักษณะนี้ จะเป็นการ Query ข้อมูลจาก Table นี่ Table เดียวเลย ซึ่งเมื่อผมนำไปทดลอง Execute มันก็ใช้เวลาไม่นานมากนะ 3 วินาทีเอง เอ๋แล้วทำไมแค่ Query ข้อมูลมันถึงมี Event ” Latch:cache buffer chain ” ได้หละ ผมจึงเปลี่ยนประเด็นไปที่เจ้า Session ที่มี Wait Class เป็น Concurrency => Event ” Latch:cache buffer chain ” ซึ่งมีจำนวนมากซะด้วย 80-85% ของ Active session ทั้งหมด

     เนื่องจากผมอยากรู้ว่า มันเยอะขนาดนี้นี่แล้วใน 1 ชม มันทำงานเยอะขนาดไหน แล้วถือครอง CPU นานรึเปล่า ( เราพูดถึงเวลาที่ถือครอง ไม่ใช่จำนวน CPU ที่ถือครอง  Oracle ดูในระดับนั้นไม่ได้ หากต้องการดู CPU ที่ Process นั้นถือครอง ต้องดูในระดับ OS ทีเ่ป็น current time เท่านั้น) ผมจึงลอง Generate AWR Report ออกมาช่วงเวลา 7-8 โมงเช้า ซึ่งถ้าที่เราประเมินมาข้างต้นถูกต้องเราต้องเห็นอะไรเกี่ยวกับเจ้า Query นี้บน Report บ้าง

ภาพที่6. ภาพนี้เป็น ข้อมูลพื้นฐาน และ Top 5 Event ของ session ในช่วงเวลาที่เราเลือกมา

จากภาพนี้ เราก็จะพบว่า  Events ที่มีมากที่สุดใน 1 ชม คือ เจ้า ” Latch:cache buffer chain ” ของเรานี่เอง 53% ของ 100% ของการทำงานแนะ ตามมาด้วย gc buffer busy ทำให้สิ่งที่เราพุ่งประเด็นไว้ตอนแรกน่าจะเป็นไปได้

ภาพที่7. ภาพนี้เป็น statement ที่มีการถือครอง CPU นานที่สุดโดยนำเวลาที่มีการใช้งานใน 1 ชม มาแสดง

     จากภาพที่ 7 เราจะเห็นได้ว่า จริงๆแล้ว statement ที่เราสงสัยเนี่ย (4 อันล่าง) มันก็ไม่ได้ใช้ CPU นานที่สุดนี่นาแค่ติด Top 10 เอง อันข้างบนนั้นโหดกว่าตั้งเยอะ Executions ก็แค่หลัก 1,000 เอง นู่นข้างบนเกือบล้านครั้งต่อชั่วโมงน่าสงสัยกว่าอีก นั่นทำให้เรายังสรุปไม่ได้ว่ามันเป็นประเด็นมาจากเจ้า statement นี้จริงๆ จริงๆแล้วเรื่องราวที่เราร่ายยาวมาทั้งหมดนี่จะจบลงง่ายมากหากเราทราบความหมายของ Latch:cache buffer chain ครับ ซึ่งผมก็พึ่งจะเคยเจอเป็นครั้งแรกเหมือนกัน ( จริงๆแล้ว ถัดจาก 10 ลงมา ผมมั่นใจว่ามันจะเป็น statement แบบนี้แหละ อีกเป็น 100 statement และ Executions เป็น 1000 เหมือนกัน 555+ )

แถมหน่อยถ้าเลื่อนลงไปอีกนิด จะเจอเลยครับ ผมดูแค่จำนวน Executions จากส่วนนี้ เห็นไหมครับมันเยอะขนาดไหน

ภาพที่7. แสดง Object ที่มีการ Read บน Memory มากที่สุด

     หากเราเลื่อนลงมาอีกนิดเราจะเห็นสิ่งนี่ครับ เห้ยนี่ไงแสงสว่างของเรา มันแสดงให้เราเห็นว่ามีการ Access บน Memory เพื่อนดึงข้อมูลจาก Object คิดเป็น 91.72% เลย ซึ่ง Object ที่เราเห็นก็ตรงกับส Table ที่เราเจอ Event latch:buffer chain ตอนแรกนั่นเอง
ต่อไปก็โยนไปให้ Developer ตรวจสอบ Table/Object ดังกล่าวครับ แล้วก็ให้เค้าแก้โปรแกรมของเค้าครับ ( หน้าที่ของเราจบแล้ว )

** เคสนี้ของผมแก้ไขด้วยการแก้ไข โปรแกรมทางฝั่ง developer และเพิ่มระยะเวลาลูปให้ถี่ลงและลบข้อมูลออกจาก Table ดังกล่าวจาก 1m -> 40k