ทำความเข้าใจกับ Systrace

systrace เป็นเครื่องมือหลักสำหรับการวิเคราะห์ประสิทธิภาพของอุปกรณ์ Android อย่างไรก็ตาม มันเป็นเครื่องห่อหุ้มเครื่องมืออื่นๆ จริงๆ เป็น wrapper ฝั่งโฮสต์รอบ atrace ปฏิบัติการด้านอุปกรณ์ที่ควบคุมการติดตาม userspace และตั้งค่า 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 บางตัวไม่มีเหตุการณ์หลังจากบางจุดในการติดตาม)

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

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

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

ตัวอย่างนี้อธิบาย systrace สำหรับไปป์ไลน์ UI ปกติ หากต้องการทำตามตัวอย่าง ให้ ดาวน์โหลดไฟล์ 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 มิลลิวินาที แต่อาจทับซ้อนกับขั้นตอนที่ 2 เนื่องจากแอป Android มักจะบัฟเฟอร์สามเท่าเสมอ (แม้ว่าแอปจะมีบัฟเฟอร์สามเท่าเสมอ อาจมีเฟรมที่รอดำเนินการเพียงเฟรมเดียวใน SurfaceFlinger ซึ่งทำให้ดูเหมือนกับการบัฟเฟอร์สองครั้ง)
6. SurfaceFlinger จะส่งเอาต์พุตสุดท้ายเพื่อแสดงพร้อมกับไดรเวอร์ของผู้จำหน่ายและกลับสู่โหมดสลีปโดยรอการปลุกของ EventThread

เดินผ่านเฟรมเริ่มต้นที่ 15409 ms:

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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