query เดียวค้าง 54 นาที ทำเว็บล่ม 504 ทั้งเว็บ เพราะ MyISAM lock

พอดีระบบงานลูกค้าตัวหนึ่งที่ผมดูแลอยู่ (Laravel + MariaDB บนเครื่องเดียว) จู่ ๆ ก็ขึ้น 504 Gateway Timeout ทุกหน้าพร้อมกัน ไม่เว้นแม้แต่หน้า login ผมเลยไล่ดูตั้งแต่ RAM ยันขนาดตาราง สุดท้ายต้นเหตุคือ query ตัวเดียวที่ค้างอยู่ 54 นาที บนตาราง MyISAM ที่มีข้อมูลแค่แสนกว่าแถว เรื่องนี้เกิดซ้ำสองครั้งกว่าผมจะจับต้นชนปลายได้ครบ เลยเขียนเก็บไว้ทั้งกลไกและวิธีแก้

ชื่อฐานข้อมูล ชื่อตาราง และหมายเลข process ในบทความเป็นชื่อสมมติทั้งหมด ส่วนคำสั่ง ตัวเลข และลำดับเหตุการณ์คือของจริง

อาการ: 504 ทุกหน้า ทั้งที่ RAM ยังเหลือเพียบ

สามอย่างแรกที่ผมเดาแล้วผิดหมด คือ RAM ไม่พอ ตารางใหญ่เกิน และ index หาย ความจริงคือ RAM เหลือ 9.5 GB ตารางที่โดนล็อกเล็กมาก และ index ของตารางนั้นยังอยู่ครบทุกตัว แค่ query ที่ยิงมาไม่ได้ใช้มัน (เรื่อง index ที่ยังอยู่แต่ใช้ไม่ได้ ผมแยกไปเล่าในบทความเรื่อง charset ข้ามฐาน เพราะเป็นต้นน้ำของเคสนี้)

เครื่องมือชิ้นเดียวที่ต้องรู้: information_schema.PROCESSLIST

ตอนเกิดเหตุผมใช้แบบสั้นที่สุดก่อน เพราะต้องการคำตอบภายในไม่กี่วินาที

-- เวอร์ชันสั้นที่ใช้จริงตอนเกิดเหตุ
SELECT ID, TIME, STATE, INFO
FROM information_schema.PROCESSLIST
WHERE TIME > 3;

พอมีเวลาหายใจแล้วค่อยใช้เวอร์ชันเต็ม อ่านง่ายกว่าเยอะ เพราะตัด newline ใน INFO ออกและเรียงตามอายุ query

SELECT ID, USER, HOST, DB, COMMAND, TIME, STATE,
       LEFT(REPLACE(INFO, '\n', ' '), 160) AS QUERY_HEAD
FROM information_schema.PROCESSLIST
WHERE COMMAND <> 'Sleep' AND TIME > 3
ORDER BY TIME DESC;

คอลัมน์ที่ต้องอ่านให้เป็นคือ STATE ครับ เพราะมันแยก "เหยื่อ" ออกจาก "ต้นเหตุ" ให้เลย

อีกคำสั่งที่ควรยิงคู่กันคือดูว่าตารางไหนกำลังถูกจับอยู่ อันนี้ตรงไปตรงมาที่สุดสำหรับ MyISAM

SHOW OPEN TABLES WHERE In_use > 0;

แล้วเช็คต่อว่าตารางที่ว่านั้นเป็น engine อะไร ใหญ่แค่ไหนจริง ๆ ตรงนี้แหละที่ทำให้ผมรู้ว่าเดาผิดมาตลอด

-- เช็คว่าตารางใน mirror เป็น engine อะไร ใหญ่แค่ไหนจริง ๆ
SELECT TABLE_SCHEMA, TABLE_NAME, ENGINE, TABLE_ROWS,
       ROUND((DATA_LENGTH+INDEX_LENGTH)/1024/1024,1) AS MB
FROM information_schema.TABLES
WHERE TABLE_SCHEMA IN ('mirror_db', 'mirror_db2', 'app_db')
ORDER BY MB DESC;

ผลที่ได้คือตารางต้นเรื่องเป็น ENGINE=MyISAM ขนาดราว 30 MB มีประมาณ 119,701 แถว เล็กจนไม่น่าเชื่อว่าจะทำเว็บล่มทั้งระบบได้

ล็อกสามชั้น ที่คนละชั้นกันคนละแบบ

ชั้นที่สามที่คนมองข้ามคือ metadata lock (MDL) ครับ มันเป็นชั้นล็อกที่อยู่เหนือ storage engine อีกที MySQL/MariaDB ใช้มันกันไม่ให้โครงสร้างตารางเปลี่ยนกลางคันขณะที่มี statement วิ่งอยู่ คำสั่งตระกูล RENAME ALTER DROP ต้องได้ MDL ระดับ exclusive ก่อน ซึ่งจะได้ก็ต่อเมื่อ statement ที่ถือ MDL แบบ shared อยู่ (ก็คือ SELECT ที่ค้างอยู่นั่นแหละ) จบลงเสียก่อน

หัวใจของเรื่องอยู่ตรงคิว MDL เป็น FIFO ปกติ SELECT ตัวใหม่ควรอ่านตารางได้สบาย แต่พอมี RENAME ไปรออยู่กลางคิวแล้ว request ใหม่ทั้งหมดต้องต่อคิวหลัง RENAME อีกที ผลคือ SELECT ธรรมดาที่ไม่ได้ทำอะไรผิดเลย ก็ต้องรอตามไปด้วย

ลูกโซ่ที่ทำให้ล่มทั้งเว็บ

ตัว query ที่เป็นต้นเรื่องหน้าตาประมาณนี้ครับ เอาตาราง mirror ที่ไม่มี index บนคอลัมน์ที่ join มาเป็นตัวตั้ง แถมยัง ORDER BY คอลัมน์ของอีกตารางหนึ่ง optimizer เลยเลือก full scan บวก filesort

-- ผิด: เอาตาราง mirror (MyISAM, ไม่มี index บนคอลัมน์ที่ join) เป็นตัวตั้ง
--      แล้วยัง ORDER BY คอลัมน์ของอีกตารางหนึ่ง
SELECT ...
FROM mirror_db2.submit_log r
JOIN app_db.job_register c ON c.ref_no = r.visit_no
ORDER BY c.doc_date DESC;

ที่น่าสนใจคือในโค้ดชุดเดียวกันมี query ตระกูลเดียวกันเป๊ะ แต่รอดมาได้ ต่างกันแค่มี WHERE คุมช่วงวันที่เท่านั้นเอง

$rows = $this->db()->select("
    SELECT a.ref_no, a.owner_id, pt.person_id, a.type_code, p.name type_name,
           a.amount charge, a.open_date, a.doc_date,
           TRIM(CONCAT(COALESCE(pt.fname,''),' ',COALESCE(pt.lname,''))) person_name
    FROM mirror_db.doc_head a
    LEFT JOIN mirror_db2.submit_log r ON r.ref_no = a.ref_no AND r.dept='IP'
    LEFT JOIN mirror_db.type_ref  p  ON p.type_code = a.type_code
    LEFT JOIN mirror_db.person    pt ON pt.owner_id = a.owner_id
    WHERE a.doc_date BETWEEN ? AND ? AND r.ref_no IS NULL AND a.amount > 0
    ORDER BY a.amount DESC", [$start, $end." 23:59:59"]);

ส่วนตัวผมถือว่า query แบบแรกคือระเบิดเวลาครับ วันที่ข้อมูลยังน้อยมันวิ่งจบใน 2 วินาที พอข้อมูลโตขึ้นสองปีมันกลายเป็น 54 นาที โดยที่ไม่มีใครแก้โค้ดสักบรรทัด

ตัวจุดชนวน: staging table + RENAME ที่ตั้งใจให้ zero-downtime

ฝั่ง cron ผมทำ mirror ข้อมูลจากระบบต้นทางมาไว้ในเครื่องเดียวกับเว็บ วิธีที่ใช้คือ dump ลง staging table ชื่อ <ตาราง>__new แล้วค่อย RENAME TABLE สลับทีเดียว ตั้งใจให้เว็บไม่ล่มระหว่าง sync

# full reload 1 ตาราง ผ่าน staging table แล้ว rename (ออกแบบให้เว็บไม่ล่มระหว่าง sync)
reload(){ # db table [where]
  db=$1; t=$2; where=$3
  stage="${t}__new"
  old="${t}__old"
  mariadb "$db" -e "DROP TABLE IF EXISTS \`$stage\`" 2>>"$LOG" || true
  if mariadb-dump $SRC $DUMPOPT ${where:+--where="$where"} "$db" "$t" 2>>"$LOG" \
       | sed -E "s/(DROP TABLE IF EXISTS|CREATE TABLE|INSERT INTO|ALTER TABLE|LOCK TABLES) \`$t\`/\1 \`${t}__new\`/g" \
       | sed -E "$FIXCS" \
       | mariadb "$db" 2>>"$LOG"; then
    if [[ "$(table_exists "$db" "$stage")" != "1" ]]; then
      echo "$(ts) reload FAIL $db.$t (missing stage table $stage)" >>"$LOG"
      return 1
    fi
    if [[ "$(table_exists "$db" "$t")" == "1" ]]; then
      if ! mariadb "$db" -e "DROP TABLE IF EXISTS \`$old\`;
        RENAME TABLE \`$t\` TO \`$old\`, \`$stage\` TO \`$t\`;
        DROP TABLE IF EXISTS \`$old\`;" 2>>"$LOG"; then
        echo "$(ts) reload FAIL $db.$t (rename failed; keeping existing table)" >>"$LOG"
        mariadb "$db" -e "DROP TABLE IF EXISTS \`$stage\`" 2>>"$LOG" || true
        return 1
      fi
    else
      if ! mariadb "$db" -e "RENAME TABLE \`$stage\` TO \`$t\`;" 2>>"$LOG"; then
        echo "$(ts) reload FAIL $db.$t (initial rename failed)" >>"$LOG"
        return 1
      fi
    fi
    echo "$(ts) reload OK   $db.$t" >>"$LOG"
  else
    mariadb "$db" -e "DROP TABLE IF EXISTS \`$stage\`" 2>/dev/null
    echo "$(ts) reload FAIL $db.$t" >>"$LOG"
    return 1
  fi
}

บรรทัดที่เป็นชนวนคือ RENAME TABLE \$t` TO `$old`, `$stage` TO `$t`;` ครับ วิธีนี้ปลอดภัยดีในวันปกติ แต่ในวันที่มี SELECT ค้างอยู่ มันกลายเป็นตัวเปลี่ยน "หน้าเดียวช้า" ให้เป็น "ทั้งเว็บตาย" เพราะมันไปนั่งขวางคิว MDL ไว้

cron ที่รันคือรอบละชั่วโมง นาทีที่ 5 มี flock กันรอบซ้อนไว้แล้ว

# /etc/cron.d/app-mirror
SHELL=/bin/bash
PATH=/usr/local/bin:/usr/bin:/bin
5 * * * * root /usr/bin/flock -n /tmp/app-hourly.lock -c '/usr/local/bin/app-hourly.sh' >> /var/www/app/storage/logs/mirrorsync.log 2>&1

แก้เฉพาะหน้า: หนึ่งคำสั่ง

1. ยิง SELECT ID,TIME,STATE,INFO FROM information_schema.PROCESSLIST WHERE TIME>3; ดูภาพรวมก่อน
2. หา ID ที่ TIME สูงผิดปกติ และ ไม่ใช่ ตัวที่ state เป็น waiting เพราะพวกนั้นคือเหยื่อ
3. สั่ง KILL ตัวนั้นตัวเดียว แล้วรอสองสามวินาทีให้คิวสลาย
4. ดู log ฝั่ง mirror ว่า RENAME วิ่งจบ หา reload OK ในไฟล์ log
5. วัดเวลาโหลดหน้าเว็บยืนยัน (ของผมกลับมา 0.3-0.7 วินาที)
6. เก็บกวาดตาราง __new / __old ที่อาจค้างอยู่จากรอบที่ล้มเหลว

KILL <id>;          -- ฆ่าทั้ง connection (ที่ใช้จริงตอนนั้น)
KILL QUERY <id>;    -- ฆ่าเฉพาะ query ปัจจุบัน เก็บ connection ไว้ (ปลอดภัยกว่าเวลามี transaction)

ถ้าอยากได้ตัวเก็บกวาดแบบอัตโนมัติไว้ก่อน one-liner นี้ใช้ได้เลย มันจะไล่ฆ่าเฉพาะ query ที่เกิน 600 วินาทีและไม่ใช่ของระบบเอง

mariadb -N -e "SELECT ID FROM information_schema.PROCESSLIST \
  WHERE COMMAND<>'Sleep' AND TIME>600 AND USER<>'system user'" \
| while read id; do echo "killing $id"; mariadb -e "KILL QUERY $id"; done

แก้ถาวร เรียงตามความคุ้ม

เรื่องแรกและคุ้มที่สุดคือเลิกใช้ MyISAM ใน mirror ครับ พอเป็น InnoDB แล้ว SELECT ยาว ๆ จะไม่ไปขวาง DDL ของคนอื่นอีก

ALTER TABLE mirror_db2.submit_log ENGINE=InnoDB ROW_FORMAT=DYNAMIC;

ถ้ามีหลายสิบตารางก็ให้ information_schema สร้าง statement ให้ทั้งชุด แล้วค่อยเอาไปรันทีเดียว

SELECT CONCAT('ALTER TABLE `',TABLE_SCHEMA,'`.`',TABLE_NAME,
              '` ENGINE=InnoDB ROW_FORMAT=DYNAMIC;') AS stmt
FROM information_schema.TABLES
WHERE ENGINE='MyISAM'
  AND TABLE_SCHEMA IN ('mirror_db','mirror_db2');

แต่แก้ตารางที่มีอยู่อย่างเดียวไม่พอ เพราะ mirror รอบหน้าจะ dump โครงสร้างเดิมกลับมาเป็น MyISAM อีก ต้องไปแก้ที่ต้นทาง pipeline ให้มันเกิดมาเป็น InnoDB ตั้งแต่แรก

# ของเดิมในสคริปต์ (จัดการ charset + row format ของ InnoDB อยู่แล้ว)
FIXCS='s/CHARSET=tis620/CHARSET=utf8mb4/g; s/CHARACTER SET tis620/CHARACTER SET utf8mb4/g; s/tis620_thai_ci/utf8mb4_unicode_ci/g; s/tis620_bin/utf8mb4_bin/g; s/ENGINE=InnoDB /ENGINE=InnoDB ROW_FORMAT=DYNAMIC /g'

# สิ่งที่ต้องเพิ่มเพื่อฆ่า MyISAM ให้สิ้นซาก
FIXCS="$FIXCS"'; s/ENGINE=MyISAM/ENGINE=InnoDB ROW_FORMAT=DYNAMIC/g'

เรื่องที่สองคือเอา cross-db JOIN ที่ไม่มีขอบเขตออกจากหน้าเว็บให้หมด ผมย้ายหน้าที่ช้าที่สุดไปอ่านตารางสรุปของแอปเองตารางเดียว คำนวณล่วงหน้าไว้ตอน cron แล้ว หน้าเว็บไม่ต้อง join ข้ามฐานอีกเลย เรื่องที่สามคือเติม index บนคีย์ที่ใช้ join จริงทั้งสองฝั่ง

-- ฝั่ง mirror: คีย์ที่หน้าเว็บใช้ join/filter
ALTER TABLE mirror_db2.submit_log
  ADD INDEX idx_ref (ref_no),
  ADD INDEX idx_visit (visit_no),
  ADD INDEX idx_ym (ym);

เรื่องที่สี่ที่ผมมองข้ามมาตลอดคือ timeout ครับ ตั้งฝั่ง client อย่างเดียวไม่พอ ต้องตั้งฝั่ง server ด้วย

SET SESSION max_statement_time = 30;      -- MariaDB (วินาที)
-- MySQL 8: SET SESSION max_execution_time = 30000;  (มิลลิวินาที, เฉพาะ SELECT)

กับดักที่ผมอยากให้ระวังเป็นพิเศษ

เครื่องมือรัน SQL แบบ ad-hoc ของผมมี guard กันเขียนกับ timeout อยู่แล้ว แต่ยังไม่สมบูรณ์ตรงที่พอ timeout แล้วมันไม่ได้ไป KILL ต่อให้

WRITE = re.compile(
    r"\b(insert|update|delete|drop|alter|create|rename|replace|truncate|"
    r"grant|revoke|load\s+data|into\s+outfile|lock\s+tables)\b",
    re.IGNORECASE,
)

def guard(sql: str) -> None:
    stripped = re.sub(r"--[^\n]*|/\*.*?\*/", "", sql, flags=re.DOTALL)
    m = WRITE.search(stripped)
    if m:
        sys.exit(f"REFUSED (read-only audit tool): พบคำสั่งเขียน '{m.group(0)}'")

อีกกับดักที่โดนตามมาอีกสองวันคือไฟล์ cron สำรอง ผมสำรองไฟล์ cron เก่าไว้ใน /etc/cron.d/ โดยตั้งชื่อเป็น .bak.<timestamp> คิดว่าปลอดภัยดี ผลคือ cron รันทั้งของเก่าและของใหม่พร้อมกัน mirror สองตัวชนกันบน staging table ชื่อเดียวกัน ตาราง mirror หายทั้งชุด เว็บขึ้น 500 ต้องกู้ด้วยการรัน mirror โหมด full ใหม่ทั้งหมด บทเรียนคือห้ามวางไฟล์ cron สำรองไว้ใน /etc/cron.d ย้ายออกไป /root/disabled-cron/ เท่านั้น

ส่วนกันรอบซ้อนของตัวสคริปต์เอง ผมใส่ flock ซ้อนอีกชั้นไว้ในสคริปต์ ไม่พึ่ง cron อย่างเดียว

if [[ "${MIRROR_LOCKED:-0}" != "1" ]]; then
  exec 9>/tmp/app-mirror.lock
  if ! flock -n 9; then
    echo "$(ts) ===== mirror skipped: another mirror is running =====" >>"$LOG"
    exit 75
  fi
  export MIRROR_LOCKED=1
fi

เช็คลิสต์สั้น ๆ ไว้ก็อปไปใช้

ข้อสุดท้ายผมยังไม่ได้ทำจริงจังในเคสนี้ครับ ตอนนี้ยังเป็นแค่ one-liner ที่รันมือ ตั้งใจจะทำเป็น cron ทุก 5 นาทีที่เตือนเข้าแชตก่อนแล้วค่อยตัดสินใจว่าจะ auto-kill ที่กี่วินาที ใครมีเพดานที่ใช้อยู่จริงในระบบตัวเองก็เอามาแลกกันได้ ผมอยากรู้ว่าคนอื่นตั้งกันที่เท่าไหร่ ตรงไหนผมอธิบายตกหล่นหรือพิมพ์ผิด เดี๋ยวกลับมาแก้เพิ่มให้ภายหลังครับ