วัดเวลาของ psql ผ่าน VPN: แยกเวลารอเครือข่ายออกจากงานของคิวรี

รายงานของคุณเสร็จในราวหนึ่งวินาทีบนโฮสต์ฐานข้อมูล และสี่วินาทีผ่าน VPN และตัวเลขที่ psql พิมพ์ชี้ตรงไปที่ฐานข้อมูล ตัวเลขนั้นเป็นนาฬิกาจับเวลาฝั่งไคลเอนต์ ไม่ใช่การวัดของเซิร์ฟเวอร์ มันครอบคลุมคำสั่งตอนออกไป การรอคำตอบ และแถวตอนกลับมา การแยกสามอย่างนี้ออกจากกันเป็นวิธีเดียวที่จะรู้ว่าต้องปรับฝั่งไหน

ตัวจับเวลาของ psql วัดอะไรจริง ๆ

\timing on เริ่มนาฬิกาจับเวลาก่อนที่ไคลเอนต์จะเขียนคำสั่งลงซ็อกเก็ตเล็กน้อย และหยุดเมื่ออ่านแถวสุดท้ายของผลลัพธ์นั้นแล้ว การทำงานของเซิร์ฟเวอร์เองอยู่ที่ใดที่หนึ่งในหน้าต่างนั้น เช่นเดียวกับทุกมิลลิวินาทีที่แพ็กเก็ตใช้ในอุโมงค์ ไม่มีสิ่งใดในเอาต์พุตแยกสองอย่างนี้ออกจากกัน EXPLAIN ก็พิมพ์ตัวเลขเช่นกัน แต่ตัวเลขนั้นเซิร์ฟเวอร์สร้างขึ้นและไม่รวมเวลารอของไคลเอนต์ สองตัวเลข สองคำถามที่ต่างกัน

เริ่มหนึ่งเซสชัน เปิดการวัดเวลาไว้ และรันคำสั่งที่คุณสนใจจากภายในเซสชันนั้น การใช้เซสชันซ้ำทำให้ค่าการเชื่อมต่ออยู่นอกการวัดครั้งแรก

psql "host=db.internal port=5432 dbname=appdb user=app" \
  -c "\timing on" \
  -c "select count(*) from orders where created_at > now() - interval '1 day';"

ตัวเลขยังรวมการส่งผลลัพธ์ซึ่งเป็นสิ่งที่ต้องการตรงนี้ ไม่รวมการแลกเปลี่ยนการเชื่อมต่อและการยืนยันตัวตนที่การเรียกใหม่จะเพิ่มเข้ามาอีกต่อไป

เปรียบเทียบคำสั่งเดียวบนสามเส้นทาง

รันคำสั่งเดียวกันผ่านซ็อกเก็ต Unix ผ่านที่อยู่ LAN และผ่านชื่อโฮสต์ VPN แล้วเปรียบเทียบทั้งสาม หากช้าเฉพาะเส้นทางสุดท้าย คิวรีก็ไม่ใช่ตัวแปร

การเรียกแต่ละครั้งเชื่อมต่อก่อนแล้วจึงวัดคำสั่ง ค่าการเชื่อมต่อจึงอยู่นอกตัวเลข ขณะที่การส่งข้อมูลยังอยู่ภายใน รักษา WHERE จำนวนแถว และเครื่องไคลเอนต์ให้เหมือนกัน มิฉะนั้นคุณกำลังเปรียบเทียบภาระงานไม่ใช่เส้นทาง

psql -h /var/run/postgresql -U app -d appdb -c "\timing on" -c "select count(*) from orders;"
psql -h 10.40.0.12 -U app -d appdb -c "\timing on" -c "select count(*) from orders;"
psql -h db.vpn.internal -U app -d appdb -c "\timing on" -c "select count(*) from orders;"

บน LAN ความต่างมักเล็กพอที่จะมองข้าม แต่ผ่าน VPN มักไม่ใช่ การเรียงสามผลลัพธ์จะบอกว่าควรโจมตีเวลารอใด

ซ็อกเก็ตโลคอลที่ช้าหมายถึงงานของเซิร์ฟเวอร์หรือการวางแผน ผลลัพธ์ LAN ที่ช้าหมายถึงคิวรีหรือปริมาณที่มันเคลื่อนย้าย มีเพียงผลลัพธ์ VPN ที่ช้าเท่านั้นที่หมายถึงความหน่วง MTU หรือแบนด์วิดท์ที่ใช้ได้บนเส้นทาง และการเปลี่ยนดัชนีไม่ช่วยแก้

ดึงเวลาทำงานของเซิร์ฟเวอร์เองออกมา

เซิร์ฟเวอร์รายงานได้ว่าใช้เวลาเท่าไร และตัวเลขนั้นคือสิ่งที่ต้องเทียบกับของไคลเอนต์ EXPLAIN พร้อม ANALYZE รันคำสั่งและพิมพ์เวลาวางแผนและเวลาทำงานในแผน ส่วน BUFFERS เพิ่มพฤติกรรมแคชซึ่งมักอธิบายการรันที่อุ่นกับการรันที่เย็น อย่าชี้มันไปที่คำสั่งเขียน เว้นแต่คุณตั้งใจจะเขียน บนรีพลิกาอ่านอย่างเดียว นี่คือที่ที่ปลอดภัยที่สุดในการเริ่ม และ เอกสารอ้างอิง psql อธิบายขอบเขตฝั่งไคลเอนต์ของตัวจับเวลา

สำหรับคำสั่งที่แอปพลิเคชันรันอยู่แล้ว pg_stat_statements รวบรวมการทำงานฝั่งเซิร์ฟเวอร์โดยไม่รันอะไรซ้ำ แถวเป็นรายคิวรีที่ถูกทำให้เป็นมาตรฐาน ดังนั้นหนึ่งรายการอาจครอบคลุมจุดเรียกหลายจุด

select calls, round(mean_exec_time::numeric, 2) as mean_ms, rows
from pg_stat_statements
order by mean_exec_time desc
limit 5;

ชื่อคอลัมน์ต่างกันตามรุ่น: PostgreSQL 13 และใหม่กว่าเปิดเผย mean_exec_time ขณะที่รุ่นเก่าเรียกมันว่า mean_time ดังนั้นตรวจสอบด้วย \d pg_stat_statements หากคิวรีนั้นให้ข้อผิดพลาด ค่าเหล่านี้ไม่รวมการวางแผนและไม่รวมการเดินทางไปยังไคลเอนต์ของคุณ การตัดออกนั้นเองที่ทำให้มันมีประโยชน์สำหรับการเปรียบเทียบ

นับการไปกลับ ไม่ใช่แค่มิลลิวินาที

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

วัดจำนวนคำสั่งแทนการประมาณ อ่านยอดรวม รันรายงานหนึ่งครั้ง แล้วอ่านอีกครั้งและลบออก

select sum(calls) as calls from pg_stat_statements;
-- run the report here
select sum(calls) as calls from pg_stat_statements;

หากเดลต้าใหญ่และทุกคำสั่งถูกบนเซิร์ฟเวอร์ การแบ่งชุดคือการแก้ไขที่คุ้มค่า รวมคิวรีที่พึ่งพากัน ใช้คำสั่งเดียวแบบเซต หรือขับลูปจากเคอร์เซอร์ ใน psql แบบโต้ตอบ, \set FETCH_COUNT 1000 ทำให้ผลลัพธ์ขนาดใหญ่มาถึงเป็นชุดและเปลี่ยนพฤติกรรมของการส่งข้อมูลและหน่วยความจำไคลเอนต์ มันไม่ได้ลดงานของเซิร์ฟเวอร์ จึงไม่ช่วยกู้คิวรีที่ช้า

ตรวจอุโมงค์เรื่องการส่งซ้ำและการหยุดของ MTU

เมื่อคำสั่งเล็กเร็วแต่ผลลัพธ์ใหญ่หยุดกลางทาง คิวรีมักปกติดีและเส้นทางไม่ดี อุโมงค์ที่ MTU ต่ำกว่าลิงก์ชั้นล่าง ประกอบกับ ICMP ที่ถูกบล็อก สร้างรูปแบบนั้นพอดี แพ็กเก็ตแรกมาถึง แพ็กเก็ตใหญ่หายไป และการส่งข้อมูลค้างจนกว่าจะลองใหม่ ตัวนับการส่งซ้ำฝั่งไคลเอนต์แสดงสิ่งนี้

เฝ้าดูซ็อกเก็ตและตัวนับเคอร์เนลขณะที่มีการส่งข้อมูลที่ตั้งใจให้ช้า ยอดการส่งซ้ำเป็นแบบสะสม ดังนั้นบันทึกก่อนและหลังแทนการอ่านตัวอย่างเดียว

ss -tin dst 10.40.0.12
netstat -s | grep -iE "retransmit|segments retransmitted"
ping -M do -s 1400 -c 3 10.40.0.12

การส่งซ้ำที่เพิ่มขึ้นระหว่างการส่งข้อมูล พร้อมกับ ping ที่สำเร็จที่ 1400 ไบต์แต่ล้มเหลวที่ 1472 ชี้ไปที่ปัญหา MTU ไม่ใช่ปัญหาฐานข้อมูล การลด MTU ของอินเทอร์เฟซอุโมงค์หรือบีบ MSS ที่เกตเวย์คือการแก้ไขตามปกติ และสามคำสั่งเดิมยืนยันได้หลังจากนั้น หากการส่งซ้ำคงที่ขณะที่การส่งข้อมูลยังช้า ให้ดูแบนด์วิดท์ที่อนุญาตให้อุโมงค์ไม่ใช่การสูญหาย

ลำดับสั้น ๆ ครอบคลุมรายงานช้าครั้งถัดไป เปรียบเทียบคำสั่งเดียวในเครื่อง บน LAN และผ่าน VPN อ่านการทำงานของเซิร์ฟเวอร์จาก EXPLAIN หรือ pg_stat_statements นับการเรียกก่อนและหลังการรันหนึ่งครั้ง และเฝ้าดูการส่งซ้ำขณะผลลัพธ์ใหญ่เคลื่อนที่ แต่ละขั้นตัดฝั่งหนึ่งของเส้นทางออก ไม่มีขั้นใดต้องเดาว่าควรเริ่มคอมโพเนนต์ใดใหม่