ทำความเข้าใจกับซิสเทรซ

systrace เป็นเครื่องมือหลักสำหรับการวิเคราะห์ประสิทธิภาพของอุปกรณ์ Android อย่างไรก็ตาม มันเป็นสิ่งห่อหุ้มเครื่องมืออื่นๆ จริงๆ มันเป็น wrapper ฝั่งโฮสต์รอบๆ atrace ซึ่งเป็นไฟล์ปฏิบัติการฝั่งอุปกรณ์ที่ควบคุมการติดตามพื้นที่ผู้ใช้และตั้งค่า ftrace และกลไกการติดตามหลักในเคอร์เนล Linux systrace ใช้ atrace เพื่อเปิดใช้งานการติดตาม จากนั้นอ่านบัฟเฟอร์ ftrace และรวมทุกอย่างไว้ในโปรแกรมดู HTML ที่มีอยู่ในตัวเอง (แม้ว่าเคอร์เนลรุ่นใหม่จะรองรับ Linux Enhanced Berkeley Packet Filter (eBPF) แต่เอกสารต่อไปนี้เกี่ยวข้องกับเคอร์เนล 3.18 (ไม่มี eFPF) เนื่องจากเป็นสิ่งที่ใช้กับ Pixel/Pixel XL)

systrace เป็นเจ้าของโดยทีมงาน Google Android และ Google Chrome และเป็นโอเพ่นซอร์สซึ่งเป็นส่วนหนึ่งของ โครงการ Catapult นอกจาก systrace แล้ว Catapult ยังมียูทิลิตี้ที่มีประโยชน์อื่นๆ อีกด้วย ตัวอย่างเช่น ftrace มีคุณสมบัติมากกว่าที่สามารถเปิดใช้งานได้โดยตรงโดย systrace หรือ atrace และมีฟังก์ชันการทำงานขั้นสูงบางอย่างที่สำคัญต่อการแก้ปัญหาประสิทธิภาพการทำงาน (คุณสมบัติเหล่านี้จำเป็นต้องเข้าถึงรูทและมักจะเป็นเคอร์เนลใหม่)

กำลังรันระบบ

เมื่อแก้ไขจุดบกพร่อง jitter บน Pixel/Pixel XL ให้เริ่มต้นด้วยคำสั่งต่อไปนี้:

./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000

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

เมื่อดำเนินการผ่านระบบ โปรดจำไว้ว่า ทุกเหตุการณ์จะถูกกระตุ้นโดยบางสิ่งบน CPU

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

ตัวอย่าง: กรอบการทำงาน

ตัวอย่างนี้อธิบายระบบสำหรับไปป์ไลน์ UI ปกติ หากต้องการทำตามตัวอย่าง ให้ดาวน์โหลดไฟล์ zip ของการติดตาม (ซึ่งรวมถึงการติดตามอื่นๆ ที่อ้างถึงในส่วนนี้ด้วย) แตกไฟล์ zip และเปิดไฟล์ systrace_tutorial.html ในเบราว์เซอร์ของคุณ ได้รับการเตือนว่า systrace นี้เป็นไฟล์ขนาดใหญ่ เว้นแต่ว่าคุณใช้ systrace ในการทำงานในแต่ละวัน นี่อาจเป็นการติดตามที่ใหญ่กว่ามากและมีข้อมูลมากกว่าที่คุณเคยเห็นในการติดตามเดียวมาก่อน

เพื่อให้มีปริมาณงานที่สม่ำเสมอและสม่ำเสมอ เช่น TouchLatency ไปป์ไลน์ UI จะมีสิ่งต่อไปนี้:

  1. EventThread ใน SurfaceFlinger ปลุกเธรด UI ของแอป โดยส่งสัญญาณว่าถึงเวลาเรนเดอร์เฟรมใหม่
  2. แอปเรนเดอร์เฟรมในเธรด UI, RenderThread และ hwuiTasks โดยใช้ทรัพยากร CPU และ GPU นี่คือความจุส่วนใหญ่ที่ใช้ไปสำหรับ UI
  3. แอปจะส่งเฟรมที่เรนเดอร์ไปยัง SurfaceFlinger โดยใช้แฟ้ม จากนั้น SurfaceFlinger จะเข้าสู่โหมดสลีป
  4. EventThread ที่สองใน SurfaceFlinger ปลุก SurfaceFlinger เพื่อทริกเกอร์องค์ประกอบและเอาต์พุตการแสดงผล หาก SurfaceFlinger พิจารณาว่าไม่มีงานที่ต้องทำ อุปกรณ์จะกลับสู่โหมดสลีป
  5. SurfaceFlinger จัดการองค์ประกอบโดยใช้ Hardware Composer (HWC)/Hardware Composer 2 (HWC2) หรือ GL องค์ประกอบของ HWC/HWC2 นั้นเร็วกว่าและใช้พลังงานน้อยกว่า แต่มีข้อจำกัดขึ้นอยู่กับระบบบนชิป (SoC) โดยปกติจะใช้เวลา ~4-6 ms แต่อาจทับซ้อนกับขั้นตอนที่ 2 ได้ เนื่องจากแอป Android มักจะมีบัฟเฟอร์สามเท่าเสมอ (ในขณะที่แอปต่างๆ จะถูกบัฟเฟอร์สามเท่าเสมอ อาจมีเพียงหนึ่งเฟรมที่รอดำเนินการรออยู่ใน SurfaceFlinger ซึ่งทำให้ดูเหมือนกับการบัฟเฟอร์สองครั้ง)
  6. SurfaceFlinger จัดส่งเอาต์พุตสุดท้ายเพื่อแสดงพร้อมกับไดรเวอร์ของผู้จำหน่าย และกลับสู่โหมดสลีป เพื่อรอการปลุก EventThread

มาดูเฟรมกันดีกว่าโดยเริ่มที่ 15409 ms:

ไปป์ไลน์ UI ปกติพร้อม EventThread ทำงานอยู่
รูปที่ 1 ไปป์ไลน์ UI ปกติ, EventThread ทำงานอยู่

รูปที่ 1 เป็นเฟรมปกติที่ล้อมรอบด้วยเฟรมปกติ ดังนั้นจึงเป็นจุดเริ่มต้นที่ดีในการทำความเข้าใจวิธีการทำงานของไปป์ไลน์ UI แถวเธรด UI สำหรับ TouchLatency มีสีที่ต่างกันในเวลาที่ต่างกัน แท่งแสดงถึงสถานะที่แตกต่างกันสำหรับเธรด:

  • สีเทา . นอนหลับ.
  • สีฟ้า. รันได้ (สามารถทำงานได้ แต่ตัวกำหนดเวลายังไม่ได้เลือกให้รัน)
  • สีเขียว. กำลังดำเนินการอยู่ (ผู้กำหนดเวลาคิดว่ากำลังทำงานอยู่)
  • สีแดง. การนอนหลับอย่างต่อเนื่อง (โดยทั่วไปคือการนอนบนล็อคในเคอร์เนล) สามารถบ่งบอกถึงโหลด I/O มีประโยชน์อย่างมากสำหรับการดีบักปัญหาด้านประสิทธิภาพ
  • ส้ม. การนอนหลับอย่างต่อเนื่องเนื่องจากโหลด I/O

หากต้องการดูสาเหตุของการสลีปอย่างต่อเนื่อง (หาได้จากจุดติดตาม sched_blocked_reason ) ให้เลือกส่วนสลีปต่อเนื่องสีแดง

ในขณะที่ EventThread กำลังทำงานอยู่ เธรด UI สำหรับ TouchLatency จะสามารถรันได้ หากต้องการดูว่ามีอะไรปลุก ให้คลิกส่วนสีน้ำเงิน

เธรด UI สำหรับ TouchLatency
รูปที่ 2 เธรด UI สำหรับ TouchLatency

รูปที่ 2 แสดงเธรด TouchLatency UI ถูกปลุกโดย tid 6843 ซึ่งสอดคล้องกับ EventThread เธรด UI จะเริ่มทำงาน เรนเดอร์เฟรม และจัดคิวเพื่อให้ SurfaceFlinger ใช้งานได้

เธรด UI จะเริ่มทำงาน เรนเดอร์เฟรม และจัดคิวเพื่อให้ SurfaceFlinger ใช้งานได้
รูปที่ 3 เธรด UI จะเริ่มทำงาน เรนเดอร์เฟรม และจัดคิวเพื่อให้ SurfaceFlinger ใช้งาน

หากเปิดใช้งานแท็ก binder_driver ในการติดตาม คุณสามารถเลือกธุรกรรม Binder เพื่อดูข้อมูลเกี่ยวกับกระบวนการทั้งหมดที่เกี่ยวข้องกับธุรกรรมนั้น

รูปที่ 4 ธุรกรรม Binder

รูปที่ 4 แสดงให้เห็นว่าที่ 15,423.65 ms Binder:6832_1 ใน SurfaceFlinger สามารถทำงานได้เนื่องจาก tid 9579 ซึ่งเป็น RenderThread ของ TouchLatency คุณยังสามารถดู QueueBuffer ได้ทั้งสองด้านของธุรกรรม Binder

ในระหว่างคิวคิวบัฟเฟอร์ทางฝั่ง SurfaceFlinger จำนวนเฟรมที่รอดำเนินการจาก TouchLatency จะเปลี่ยนจาก 1 เป็น 2

เฟรมที่ค้างอยู่เปลี่ยนจาก 1 เป็น 2
รูปที่ 5 เฟรมที่ค้างอยู่เปลี่ยนจาก 1 เป็น 2

รูปที่ 5 แสดงการบัฟเฟอร์สามเท่า โดยมีสองเฟรมที่เสร็จสมบูรณ์ และแอปกำลังจะเริ่มเรนเดอร์หนึ่งในสาม เนื่องจากเราได้ลบบางเฟรมไปแล้ว ดังนั้นแอปจะเก็บเฟรมที่รอดำเนินการไว้สองเฟรม แทนที่จะเป็นหนึ่งเฟรมเพื่อหลีกเลี่ยงไม่ให้เฟรมหลุดอีก

หลังจากนั้นไม่นาน เธรดหลักของ SurfaceFlinger ก็ถูกปลุกโดย EventThread ที่สอง เพื่อให้สามารถส่งออกเฟรมที่ค้างอยู่แบบเก่าไปยังจอแสดงผล:

เธรดหลักของ SurfaceFlinger ถูกปลุกโดย EventThread ที่สอง
รูปที่ 6 เธรดหลักของ SurfaceFlinger ถูกปลุกโดย EventThread ที่สอง

ก่อนอื่น SurfaceFlinger จะสลักบัฟเฟอร์ที่ค้างอยู่แบบเก่า ซึ่งจะทำให้จำนวนบัฟเฟอร์ที่ค้างอยู่ลดลงจาก 2 เป็น 1

ก่อนอื่น SurfaceFlinger จะล็อคเข้ากับบัฟเฟอร์ที่ค้างอยู่แบบเก่า
รูปที่ 7 SurfaceFlinger จะล็อคเข้ากับบัฟเฟอร์เก่าที่ค้างอยู่ก่อน

หลังจากล็อคบัฟเฟอร์แล้ว SurfaceFlinger จะตั้งค่าองค์ประกอบและส่งเฟรมสุดท้ายไปยังจอแสดงผล (บางส่วนของส่วนเหล่านี้เปิดใช้งานโดยเป็นส่วนหนึ่งของจุดติดตาม mdss ดังนั้นจึงอาจไม่รวมอยู่ใน SoC ของคุณ)

SurfaceFlinger ตั้งค่าองค์ประกอบและส่งเฟรมสุดท้าย
รูปที่ 8 SurfaceFlinger ตั้งค่าองค์ประกอบและส่งเฟรมสุดท้าย

ถัดไป mdss_fb0 จะเริ่มทำงานบน CPU 0 mdss_fb0 คือเคอร์เนลเธรดของไปป์ไลน์การแสดงผลสำหรับส่งออกเฟรมที่เรนเดอร์ไปยังจอแสดงผล เราสามารถเห็น mdss_fb0 เป็นแถวของตัวเองในการติดตาม (เลื่อนลงเพื่อดู)

mdss_fb0 เริ่มทำงานบน CPU 0
รูปที่ 9. mdss_fb0 เริ่มทำงานบน CPU 0

mdss_fb0 ตื่นขึ้นมา ทำงานเป็นเวลาสั้นๆ เข้าสู่โหมดสลีปอย่างต่อเนื่อง จากนั้นจึงกลับมาทำงานอีกครั้ง

ตัวอย่าง: กรอบไม่ทำงาน

ตัวอย่างนี้อธิบายระบบที่ใช้ในการแก้ไขจุดบกพร่องของ Pixel/Pixel XL jitter หากต้องการทำตามตัวอย่าง ให้ดาวน์โหลดไฟล์ zip ของการติดตาม (ซึ่งรวมถึงการติดตามอื่นๆ ที่อ้างถึงในส่วนนี้) แตกไฟล์ zip และเปิดไฟล์ systrace_tutorial.html ในเบราว์เซอร์ของคุณ

เมื่อคุณเปิด systrace คุณจะเห็นสิ่งนี้:

TouchLatency ทำงานบน Pixel XL โดยเปิดใช้งานตัวเลือกส่วนใหญ่
รูปที่ 10 TouchLatency ทำงานบน Pixel XL (ตัวเลือกส่วนใหญ่เปิดใช้งาน รวมถึงจุดติดตาม mdss และ kgsl)

เมื่อต้องการค้นหา jank ให้ตรวจสอบแถว FrameMissed ใต้ SurfaceFlinger FrameMissed คือการปรับปรุงคุณภาพชีวิตโดย HWC2 เมื่อดูระบบสำหรับอุปกรณ์อื่น แถว FrameMissed อาจไม่ปรากฏหากอุปกรณ์ไม่ได้ใช้ HWC2 ไม่ว่าในกรณีใด FrameMissed มีความสัมพันธ์กับ SurfaceFlinger ที่ขาดหนึ่งในรันไทม์ปกติอย่างยิ่งและการนับบัฟเฟอร์ที่รอดำเนินการไม่เปลี่ยนแปลงสำหรับแอป ( com.prefabulated.touchlatency ) ที่ vsync

FrameMissed สัมพันธ์กับ SurfaceFlinger
รูปที่ 11 ความสัมพันธ์ของ FrameMissed กับ SurfaceFlinger

รูปที่ 11 แสดงเฟรมที่พลาดที่ 15598.29&nbps;ms SurfaceFlinger ตื่นช่วงสั้นๆ ในช่วงเวลา vsync และกลับไปเข้าสู่โหมดสลีปโดยไม่ได้ทำงานใดๆ ซึ่งหมายความว่า SurfaceFlinger พิจารณาแล้วว่ามันไม่คุ้มค่าที่จะพยายามส่งเฟรมไปที่จอแสดงผลอีกครั้ง ทำไม

หากต้องการทำความเข้าใจว่าไปป์ไลน์ใช้งานไม่ได้สำหรับเฟรมนี้อย่างไร ก่อนอื่นให้ตรวจสอบตัวอย่างเฟรมการทำงานด้านบนเพื่อดูว่าไปป์ไลน์ UI ปกติปรากฏใน systrace อย่างไร เมื่อพร้อมแล้วให้กลับเข้าสู่เฟรมที่ไม่ได้รับและทำงานย้อนกลับ โปรดสังเกตว่า SurfaceFlinger ตื่นและเข้าสู่โหมดสลีปทันที เมื่อดูจำนวนเฟรมที่รอดำเนินการจาก TouchLatency จะมีสองเฟรม (เป็นเบาะแสที่ดีที่จะช่วยพิจารณาว่าเกิดอะไรขึ้น)

SurfaceFlinger ตื่นและเข้าสู่โหมดสลีปทันที
รูปที่ 12 SurfaceFlinger ตื่นและเข้าสู่โหมดสลีปทันที

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

เนื่องจากเปิดใช้งาน mdss และจุดติดตาม sync เราจึงสามารถรับข้อมูลเกี่ยวกับรั้ว (แชร์ระหว่างไดรเวอร์จอแสดงผลและ SurfaceFlinger) ที่ควบคุมว่าจะส่งเฟรมไปยังจอแสดงผลเมื่อใด รั้วเหล่านี้แสดงอยู่ภายใต้ mdss_fb0_retire ซึ่งระบุเมื่อมีเฟรมปรากฏบนจอแสดงผล รั้วเหล่านี้มีให้เป็นส่วนหนึ่งของหมวดหมู่การติดตาม sync รั้วใดที่สอดคล้องกับเหตุการณ์เฉพาะใน SurfaceFlinger ขึ้นอยู่กับ SOC และสแต็กไดรเวอร์ของคุณ ดังนั้นควรทำงานร่วมกับผู้จำหน่าย SOC ของคุณเพื่อทำความเข้าใจความหมายของหมวดหมู่รั้วในการติดตามของคุณ

mdss_fb0_ออกจากรั้ว
รูปที่ 13 mdss_fb0_ถอนรั้ว

รูปที่ 13 แสดงเฟรมที่แสดงเป็นเวลา 33 มิลลิวินาที ไม่ใช่ 16.7 มิลลิวินาทีตามที่คาดไว้ ผ่านครึ่งทางนั้น เฟรมนั้นควรถูกแทนที่ด้วยเฟรมใหม่ แต่ไม่ใช่ ดูเฟรมก่อนหน้าแล้วมองหาอะไรก็ได้

เฟรมก่อนหน้าถึงเฟรมที่ถูกจับ
รูปที่ 14 เฟรมก่อนหน้าถึงเฟรมที่ถูกจับ

รูปที่ 14 แสดง 14.482 ms ต่อเฟรม ส่วนสองเฟรมที่เสียหายคือ 33.6 มิลลิวินาที ซึ่งเป็นโดยประมาณที่เราคาดหวังสำหรับสองเฟรม (เราเรนเดอร์ที่ 60 Hz, 16.7 มิลลิวินาทีต่อเฟรม ซึ่งใกล้เคียงกัน) แต่ 14.482 ms นั้นไม่ได้ใกล้เคียงกับ 16.7 ms เลย ซึ่งบ่งบอกว่ามีบางอย่างผิดปกติอย่างมากกับไปป์จอแสดงผล

ตรวจสอบให้แน่ชัดว่ารั้วนั้นสิ้นสุดที่จุดใดเพื่อพิจารณาว่าสิ่งใดควบคุม

สำรวจปลายรั้ว
รูปที่ 15 ตรวจสอบปลายรั้ว

คิวงานประกอบด้วย __vsync_retire_work_handler ซึ่งทำงานเมื่อรั้วมีการเปลี่ยนแปลง เมื่อดูแหล่งที่มาของเคอร์เนล คุณจะเห็นว่าเป็นส่วนหนึ่งของไดรเวอร์การแสดงผล ดูเหมือนว่าจะอยู่บนเส้นทางวิกฤติสำหรับไปป์ไลน์การแสดงผล ดังนั้นจึงต้องทำงานโดยเร็วที่สุด สามารถใช้งานได้ประมาณ 70 คน (ไม่ใช่ความล่าช้าในการตั้งเวลาที่ยาวนาน) แต่เป็นคิวงานและอาจกำหนดเวลาไม่ถูกต้อง

ตรวจสอบเฟรมก่อนหน้าเพื่อดูว่ามีส่วนหรือไม่ บางครั้งความกระวนกระวายใจอาจเพิ่มขึ้นเมื่อเวลาผ่านไปและส่งผลให้พลาดกำหนดเวลาในที่สุด

เฟรมก่อนหน้า
รูปที่ 16 เฟรมก่อนหน้า

มองไม่เห็นบรรทัดที่รันได้บน kworker เนื่องจากผู้ดูจะเปลี่ยนเป็นสีขาวเมื่อถูกเลือก แต่สถิติบอกเล่าเรื่องราว: ความล่าช้าของตัวกำหนดตารางเวลา 2.3 มิลลิวินาทีสำหรับส่วนหนึ่งของเส้นทางวิกฤตไปป์ไลน์การแสดงผลนั้น ไม่ดี ก่อนดำเนินการต่อ ให้แก้ไขความล่าช้าด้วยการย้ายส่วนนี้ของเส้นทางวิกฤตไปป์ไลน์การแสดงผลจากคิวงาน (ซึ่งทำงานเป็นเธรด CFS SCHED_OTHER ) ไปยัง kthread SCHED_FIFO เฉพาะ ฟังก์ชันนี้ต้องการการรับประกันกำหนดเวลาซึ่งคิวงานไม่สามารถให้ได้ (และไม่ได้ตั้งใจ)

นี่คือสาเหตุของ jank หรือไม่? มันยากที่จะพูดสรุป นอกเหนือจากกรณีที่ง่ายต่อการวินิจฉัย เช่น การแย่งชิงการล็อกเคอร์เนลทำให้เธรดที่มีความสำคัญต่อการแสดงผลเข้าสู่โหมดสลีป การติดตามมักจะไม่ได้ระบุปัญหา ความกระวนกระวายใจนี้อาจเป็นสาเหตุของเฟรมที่ตกหรือไม่? อย่างแน่นอน. เวลาของรั้วควรอยู่ที่ 16.7 มิลลิวินาที แต่ไม่ได้ใกล้เคียงเลยในเฟรมที่นำไปสู่เฟรมที่ดร็อป เมื่อพิจารณาว่าไปป์ไลน์การแสดงผลเชื่อมโยงกันแน่นเพียงใด อาจเป็นไปได้ที่ความกระวนกระวายใจรอบ ๆ การกำหนดเวลาของรั้วส่งผลให้เฟรมหลุด

ในตัวอย่างนี้ โซลูชันเกี่ยวข้องกับการแปลง __vsync_retire_work_handler จากคิวงานไปเป็น kthread เฉพาะ ส่งผลให้มีการปรับปรุงความกระวนกระวายใจอย่างเห็นได้ชัดและลดความผิดพลาดในการทดสอบลูกกระดอน การติดตามที่ตามมาแสดงการกำหนดเวลาของรั้วที่ใกล้เคียงกับ 16.7 มิลลิวินาที