☕ 5-Min Tech Story #38

คำสาป log.info(): แค่สั่งพิมพ์บันทึกบรรทัดเดียว ทำไมแอปถึงอืดจนติดเบรกเกอร์?

⏱️ ใช้เวลาอ่านประมาณ: 4 นาที 20 วินาที

ในโค้ดทางเดินหลัก (Hot Path) คุณเขียนคำสั่งธรรมดาๆ ไว้ 1 บรรทัดด้วยความปรารถนาดี:

        log.info("Processing payment for user: {} with payload: {}", userId, payload);
      

บนเครื่องพัฒนา (Localhost) มันทำงานฉลุยในเวลาไม่ถึง 0.05 มิลลิวินาที... แต่ในคืนวัน Double Digit ที่มีคำสั่งซื้อทะลักเข้ามา 10,000 Requests/วินาที Response Time ของระบบกลับพุ่งทะลุ 3 วินาที และแอปเริ่มปฏิเสธการเชื่อมต่อ!

พอทำ Thread Dump ดู สาเหตุไม่ได้มาจากคำนวณเลขหนัก ไม่ได้รอฐานข้อมูล แต่ Thread นับร้อยตัวกำลังเข้าคิวแย่งกันตายอยู่ที่จุดบันทึก Log!

🧱 กำแพงความจริง: Synchronous Logging & Disk I/O Wait

ไลบรารียอดนิยมอย่าง Logback หรือ Log4j ในโหมดมาตรฐานถูกตั้งค่าให้บันทึกแบบ Synchronous (รอก่อนจนกว่าจะเขียนเสร็จ)

นั่นหมายความว่าทุกครั้งที่เธรดของแอปพลิเคชันเดินมาเจอ log.info():

เธรดนั้นต้องหยุดทำงานทางธุรกิจทันที
ประกอบข้อความ (String Concatenation & Object Serialization) บน RAM
แย่งคิวยึดกุญแจ Lock (Synchronized Block) ของไฟล์ปลายทาง เพื่อไม่ให้ตัวอักษรของแต่ละ Request ปนกันมั่ว
สั่ง Kernel เขียนข้อมูลลงดิสก์หรือส่งออก Console (Standard Output)

"ดิสก์หรือคอนโซลทำงานช้ากว่า RAM และ CPU เป็นพันเท่า... เมื่อเธรด 200 ตัวต้องมารอส่งสมุดบันทึกให้พนักงานคนเดียวจดทีละบรรทัด ทั้งระบบจึงติดคอขวด (Lock Contention) จนแทบหยุดนิ่ง!"

🐳 กับดัก Kubernetes: stdout ไม่ใช่ท่อลมไร้แรงต้าน

ในยุค Containerized ทุกคนถูกสอนให้พ่น Log ออกทาง stdout (Standard Out) เพื่อให้ Agent อย่าง Fluentbit หรือ Promtail กวาดไปส่ง Loki/Elasticsearch

แต่ในระบบปฏิบัติการ Linux การเขียนใส่ stdout คือการเขียนผ่าน Pipe Buffer ขนาด 64KB:

ถ้าแอปของคุณพ่น Log รัวเร็วกว่าที่ Container Runtime (Docker/containerd) จะสูบออกไปได้ทัน
ท่อ 64KB นั้นจะเต็มปริ่มอย่างรวดเร็ว!
และตามกฎของ Kernel คำสั่ง write() จะ บล็อกเธรดของแอปพลิเคชันไว้ทันที จนกว่าท่อจะมีที่ว่าง!

🛡️ 2 คาถาปลดแอก: Async Appender & Ring Buffer

1. สลับมาใช้ Asynchronous Appender:

อย่าปล่อยให้เธรดทำงานทางธุรกิจต้องไปจับปากกาเขียนแผ่นดิสก์เอง ให้เธรดโยนข้อความใส่คิวหน่วยความจำแล้วเดินหน้าทำงานต่อทันที:

        <!-- ตัวอย่างคอนฟิก Logback AsyncAppender -->

        <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">

          <appender-ref ref="FILE" />

          <queueSize>10240</queueSize>

          <neverBlock>true</neverBlock> <!-- ทิ้ง Log ดีกว่าปล่อยให้แอปค้าง! -->

        </appender>

2. หรือก้าวสู่นิพพานด้วย Log4j2 + LMAX Disruptor:

Log4j2 มีระบบ Async Loggers ที่ขับเคลื่อนด้วยโครงสร้าง Ring Buffer (LMAX Disruptor) แบบ Lock-free ทำให้การพ่น Log รองรับได้มากกว่า 18 ล้านข้อความต่อวินาที โดยมี Latency แฝงแค่ระดับนาโนวินาทีเท่านั้น

💡 5-Min Takeaway

"การสังเกตการณ์ระบบ (Observability) ต้องไม่เข้ามาทำลายประสิทธิภาพของตัวระบบเอง" คำสั่งบันทึก Log บรรทัดเดียวในลูปที่โหลดสูงมีต้นทุนมหาศาลจากการแย่งล็อกและ I/O บล็อก จงเปิดใช้งาน Asynchronous Logging เสมอ, หลีกเลี่ยงการประกอบ String ขนาดใหญ่ใน Hot Path, และจำไว้ว่าในยามวิกฤต การยอมทิ้ง Log บางบรรทัดด้วย neverBlock=true ย่อมดีกว่าการปล่อยให้ระบบล้มทั้งระบบต่อหน้าลูกค้า