Sử dụng ftrace

ftrace là một công cụ gỡ lỗi để hiểu những gì đang diễn ra bên trong nhân Linux. Các phần sau đây mô tả chi tiết chức năng ftrace cơ bản, cách sử dụng ftrace với atrace (ghi lại các sự kiện kernel) và ftrace động.

Để biết chi tiết về chức năng ftrace nâng cao không có sẵn từ systrace, hãy tham khảo tài liệu ftrace tại <kernel tree>/Documentation/trace/ftrace.txt .

Ghi lại các sự kiện kernel bằng atrace

atrace ( frameworks/native/cmds/atrace ) sử dụng ftrace để ghi lại các sự kiện kernel. Đổi lại, systrace.py (hoặc run_systrace.py trong các phiên bản sau của Catapult ) sử dụng adb để chạy atrace trên thiết bị. atrace thực hiện như sau:

• Thiết lập theo dõi chế độ người dùng bằng cách đặt thuộc tính ( debug.atrace.tags.enableflags ).
• Kích hoạt chức năng ftrace mong muốn bằng cách ghi vào các nút sysfs ftrace thích hợp. Tuy nhiên, vì ftrace hỗ trợ nhiều tính năng hơn nên bạn có thể tự thiết lập một số nút sysfs sau đó sử dụng atrace.

Ngoại trừ việc theo dõi thời gian khởi động, hãy dựa vào việc sử dụng atrace để đặt thuộc tính thành giá trị thích hợp. Thuộc tính là mặt nạ bit và không có cách nào tốt để xác định giá trị chính xác ngoài việc xem tiêu đề thích hợp (có thể thay đổi giữa các bản phát hành Android).

Kích hoạt sự kiện ftrace

Các nút sysfs ftrace nằm trong /sys/kernel/tracing và các sự kiện trace được chia thành các danh mục trong /sys/kernel/tracing/events .

Để bật các sự kiện trên cơ sở từng danh mục, hãy sử dụng:

echo 1 > /sys/kernel/tracing/events/irq/enable

Để bật các sự kiện trên cơ sở từng sự kiện, hãy sử dụng:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

Nếu các sự kiện bổ sung đã được kích hoạt bằng cách ghi vào các nút sysfs, chúng sẽ không được đặt lại bởi atrace. Một mẫu phổ biến để mang lại thiết bị Qualcomm là bật các điểm theo dõi kgsl (GPU) và mdss (đường dẫn hiển thị), sau đó sử dụng atrace hoặc systrace :

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

Bạn cũng có thể sử dụng ftrace mà không cần atrace hoặc systrace, điều này rất hữu ích khi bạn chỉ muốn theo dõi kernel (hoặc nếu bạn đã dành thời gian để viết thuộc tính theo dõi chế độ người dùng bằng tay). Để chạy chỉ ftrace:

1. Đặt kích thước bộ đệm thành giá trị đủ lớn cho dấu vết của bạn:

   echo 96000 > /sys/kernel/tracing/buffer_size_kb
   

2. Kích hoạt tính năng theo dõi:

   echo 1 > /sys/kernel/tracing/tracing_on
   

3. Chạy thử nghiệm của bạn, sau đó tắt tính năng theo dõi:

   echo 0 > /sys/kernel/tracing/tracing_on
   

4. Kết xuất dấu vết:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
   

trace_output cung cấp dấu vết ở dạng văn bản. Để trực quan hóa nó bằng Catapult, hãy lấy kho lưu trữ Catapult từ GitHub và chạy trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

Theo mặc định, điều này ghi trace_file.html vào cùng thư mục.

Sự kiện tương quan

Việc xem xét trực quan hóa Catapult và nhật ký ftrace cùng một lúc thường rất hữu ích; ví dụ: một số sự kiện ftrace (đặc biệt là các sự kiện dành riêng cho nhà cung cấp) không được Catapult hiển thị. Tuy nhiên, dấu thời gian của Catapult có liên quan đến sự kiện đầu tiên trong dấu vết hoặc với dấu thời gian cụ thể do atrace kết xuất, trong khi dấu thời gian ftrace thô dựa trên nguồn đồng hồ tuyệt đối cụ thể trong nhân Linux.

Để tìm một sự kiện ftrace nhất định từ sự kiện Catapult:

1. Mở nhật ký ftrace thô. Dấu vết trong các phiên bản gần đây của systrace được nén theo mặc định:
   • Nếu bạn đã chụp systrace của mình bằng --no-compress , thì đây là tệp html trong phần bắt đầu bằng BEGIN TRACE.
   • Nếu không, hãy chạy html2trace từ cây Catapult ( tracing/bin/html2trace ) để giải nén dấu vết.
2. Tìm dấu thời gian tương đối trong trực quan hóa Catapult.
3. Tìm dòng ở đầu dấu vết chứa tracing_mark_sync . Nó sẽ trông giống như thế này:

   <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
   

   
   Nếu dòng này không tồn tại (hoặc nếu bạn sử dụng ftrace mà không có atrace), thì thời gian sẽ tương đối so với sự kiện đầu tiên trong nhật ký ftrace.
   1. Thêm dấu thời gian tương đối (tính bằng mili giây) vào giá trị tính bằng parent_ts (tính bằng giây).
   2. Tìm kiếm dấu thời gian mới.

Những bước này sẽ đưa bạn đến (hoặc ít nhất là rất gần) sự kiện.

Sử dụng ftrace động

Khi systrace và ftrace tiêu chuẩn không đủ, sẽ có một giải pháp cuối cùng: năng động ftrace . Dynamic ftrace liên quan đến việc viết lại mã hạt nhân sau khi khởi động và kết quả là nó không có sẵn trong hạt nhân sản xuất vì lý do bảo mật. Tuy nhiên, mọi lỗi khó khăn về hiệu suất trong năm 2015 và 2016 cuối cùng đều có nguyên nhân gốc rễ bằng cách sử dụng ftrace động. Nó đặc biệt mạnh mẽ trong việc gỡ lỗi các chế độ ngủ không bị gián đoạn vì bạn có thể nhận được dấu vết ngăn xếp trong kernel mỗi khi bạn nhấn chức năng kích hoạt chế độ ngủ không bị gián đoạn. Bạn cũng có thể gỡ lỗi các phần bị vô hiệu hóa các ngắt và ưu tiên, điều này có thể rất hữu ích cho việc chứng minh vấn đề.

Để bật ftrace động, hãy chỉnh sửa cấu hình mặc định của kernel:

1. Xóa CONFIG_STRICT_MEMORY_RWX (nếu có). Nếu bạn đang dùng phiên bản 3.18 trở lên và arm64 thì nó không có ở đó.
2. Thêm các mục sau: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y và CONFIG_PREEMPT_TRACER=y
3. Xây dựng lại và khởi động kernel mới.
4. Chạy phần sau để kiểm tra các công cụ theo dõi có sẵn:

   cat /sys/kernel/tracing/available_tracers
   

5. Xác nhận lệnh trả về function , irqsoff , preemptoff và preemptirqsoff .
6. Chạy phần sau để đảm bảo ftrace động đang hoạt động:

   cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
   

Sau khi hoàn thành các bước này, bạn có sẵn ftrace động, trình phân tích hàm, trình phân tích irqsoff và trình phân tích ưu tiên. Chúng tôi thực sự khuyên bạn nên đọc tài liệu ftrace về các chủ đề này trước khi sử dụng chúng vì chúng mạnh mẽ nhưng phức tạp. irqsoff và preemptoff chủ yếu hữu ích trong việc xác nhận rằng trình điều khiển có thể tắt chế độ ngắt hoặc ưu tiên quá lâu.

Trình lược tả hàm là tùy chọn tốt nhất cho các vấn đề về hiệu suất và thường được sử dụng để tìm ra vị trí của hàm được gọi.

Hiển thị vấn đề: Ảnh HDR + kính ngắm xoay

Trong vấn đề này, việc sử dụng Pixel XL để chụp ảnh HDR+ rồi xoay ngay kính ngắm luôn gây ra hiện tượng giật. Chúng tôi đã sử dụng trình phân tích hàm để gỡ lỗi sự cố trong vòng chưa đầy một giờ. Để làm theo ví dụ, hãy tải xuống tệp zip chứa dấu vết (cũng bao gồm các dấu vết khác được đề cập trong phần này), giải nén tệp và mở tệp trace_30898724.html trong trình duyệt của bạn.

Dấu vết cho thấy một số luồng trong quy trình máy chủ camera bị chặn ở chế độ ngủ liên tục trên ion_client_destroy . Đó là một chức năng đắt tiền, nhưng nó hiếm khi được gọi vì các máy khách ion phải bao gồm nhiều phân bổ. Ban đầu, lỗi rơi vào mã Hexagon trong Halide, đây thực sự là một trong những thủ phạm (nó tạo ra một ứng dụng khách mới cho mỗi lần phân bổ ion và phá hủy ứng dụng khách đó khi việc phân bổ được giải phóng, điều này quá tốn kém). Việc chuyển sang một ứng dụng khách ion duy nhất cho tất cả hoạt động phân bổ Hexagon đã cải thiện tình hình nhưng tình trạng giật vẫn chưa được khắc phục.

Tại thời điểm này, chúng ta cần biết ai đang gọi ion_client_destroy , vì vậy đã đến lúc sử dụng hàm profiler:

1. Vì các hàm đôi khi được trình biên dịch đổi tên, nên hãy xác nhận ion_client_destroy có ở đó bằng cách sử dụng:

   cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
   

2. Sau khi xác nhận nó ở đó, hãy sử dụng nó làm bộ lọc ftrace:

   echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
   

3. Bật trình lược tả chức năng:

   echo function > /sys/kernel/tracing/current_tracer
   

4. Bật dấu vết ngăn xếp bất cứ khi nào hàm lọc được gọi:

   echo func_stack_trace > /sys/kernel/tracing/trace_options
   

5. Tăng kích thước bộ đệm:

   echo 64000 > /sys/kernel/tracing/buffer_size_kb
   

6. Bật truy tìm:

   echo 1 > /sys/kernel/tracing/trace_on
   

7. Chạy thử nghiệm và nhận được dấu vết:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace
   

8. Xem dấu vết để xem rất nhiều dấu vết ngăn xếp:

       cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
       cameraserver-643   [003] ...1    94.192997: <stack trace>
    => ftrace_ops_no_ops
    => ftrace_graph_call
    => ion_client_destroy
    => ion_release
    => __fput
    => ____fput
    => task_work_run
    => do_notify_resume
    => work_pending
    

Dựa trên việc kiểm tra trình điều khiển ion, chúng ta có thể thấy rằng ion_client_destroy đang bị spam bởi chức năng không gian người dùng đóng fd thành /dev/ion , không phải trình điều khiển hạt nhân ngẫu nhiên. Bằng cách tìm kiếm \"/dev/ion\" trong cơ sở mã Android, chúng tôi thấy một số trình điều khiển của nhà cung cấp thực hiện điều tương tự như trình điều khiển Hexagon và mở/đóng /dev/ion (tạo và hủy ứng dụng khách ion mới) mỗi khi họ cần phân bổ ion mới. Việc thay đổi những điều đó để sử dụng một máy khách ion duy nhất trong suốt thời gian của quy trình đã khắc phục được lỗi.

---

Nếu dữ liệu từ trình lược tả hàm không đủ cụ thể, bạn có thể kết hợp các điểm theo dõi ftrace với trình lược tả hàm. Các sự kiện ftrace có thể được kích hoạt theo cách giống hệt như bình thường và chúng sẽ được xen kẽ với dấu vết của bạn. Điều này thật tuyệt nếu thỉnh thoảng có một chế độ ngủ kéo dài không bị gián đoạn trong một chức năng cụ thể mà bạn muốn gỡ lỗi: đặt bộ lọc ftrace thành chức năng bạn muốn, bật điểm theo dõi, theo dõi. Bạn có thể phân tích cú pháp dấu vết kết quả bằng trace2html , tìm sự kiện bạn muốn, sau đó lấy dấu vết ngăn xếp lân cận trong dấu vết thô.

Sử dụng lockstat

Đôi khi, ftrace là không đủ và bạn thực sự cần phải gỡ lỗi những gì có vẻ là xung đột khóa kernel. Có thêm một tùy chọn kernel đáng thử: CONFIG_LOCK_STAT . Đây là giải pháp cuối cùng vì rất khó để hoạt động trên thiết bị Android vì nó làm tăng kích thước của hạt nhân vượt quá mức mà hầu hết các thiết bị có thể xử lý.

Tuy nhiên, lockstat sử dụng cơ sở hạ tầng khóa gỡ lỗi, rất hữu ích cho nhiều ứng dụng khác. Mọi người làm việc trong quá trình nâng cấp thiết bị nên tìm ra cách nào đó để tùy chọn đó hoạt động trên mọi thiết bị vì sẽ có lúc bạn nghĩ "Giá như tôi có thể bật LOCK_STAT thì tôi có thể xác nhận hoặc bác bỏ vấn đề này trong vòng năm phút thay vì Năm ngày."

Hiển thị sự cố: Dừng ở SCHED_FIFO khi các lõi ở mức tải tối đa không phải SCHED_FIFO

Trong sự cố này, luồng SCHED_FIFO bị đình trệ khi tất cả các lõi đều ở mức tải tối đa với các luồng không phải SCHED_FIFO. Chúng tôi có dấu vết cho thấy sự tranh chấp khóa đáng kể trên một fd trong ứng dụng VR nhưng chúng tôi không thể dễ dàng xác định fd đang sử dụng. Để làm theo ví dụ, hãy tải xuống tệp zip chứa dấu vết (cũng bao gồm các dấu vết khác được đề cập trong phần này), giải nén tệp và mở tệp trace_30905547.html trong trình duyệt của bạn.

Chúng tôi đã đưa ra giả thuyết rằng chính ftrace là nguồn gốc của sự tranh chấp khóa, khi một luồng có mức độ ưu tiên thấp sẽ bắt đầu ghi vào ống ftrace và sau đó được ưu tiên trước khi nó có thể nhả khóa. Đây là trường hợp xấu nhất đã trở nên trầm trọng hơn do hỗn hợp các luồng có mức độ ưu tiên cực thấp ghi vào điểm đánh dấu ftrace cùng với một số luồng có mức độ ưu tiên cao hơn quay trên CPU để mô phỏng một thiết bị đã được tải hoàn toàn.

Vì chúng tôi không thể sử dụng ftrace để gỡ lỗi nên chúng tôi đã làm cho LOCK_STAT hoạt động rồi tắt tất cả tính năng theo dõi khác khỏi ứng dụng. Kết quả cho thấy xung đột khóa thực sự là từ ftrace vì không có xung đột nào xuất hiện trong dấu vết khóa khi ftrace không chạy.

---

Nếu bạn có thể khởi động kernel bằng tùy chọn cấu hình, việc theo dõi khóa tương tự như ftrace:

1. Kích hoạt tính năng theo dõi:

   echo 1 > /proc/sys/kernel/lock_stat
   

2. Chạy thử nghiệm của bạn.
3. Vô hiệu hóa theo dõi:

   echo 0 > /proc/sys/kernel/lock_stat
   

4. Xóa dấu vết của bạn:

   cat /proc/lock_stat > /data/local/tmp/lock_stat
   

Để được trợ giúp diễn giải kết quả đầu ra, hãy tham khảo tài liệu lockstat tại <kernel>/Documentation/locking/lockstat.txt .

Sử dụng dấu vết của nhà cung cấp

Trước tiên hãy sử dụng điểm theo dõi ngược dòng, nhưng đôi khi bạn sẽ cần sử dụng điểm theo dõi của nhà cung cấp:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

Điểm theo dõi có thể mở rộng bằng dịch vụ HAL cho phép bạn thêm các điểm/danh mục theo dõi cụ thể của thiết bị. Tracepoint được tích hợp với perfetto, atrace/systrace và ứng dụng theo dõi hệ thống trên thiết bị.

Các API để triển khai điểm/danh mục theo dõi là:

• listCategories() tạo ra (vec<TracingCategory> danh mục);
• EnableCategories(vec<string> Category) tạo ra (Trạng thái trạng thái);
• vô hiệu hóaAllCategories() tạo ra (Trạng thái trạng thái);

Để biết thêm thông tin, hãy tham khảo định nghĩa HAL và cách triển khai mặc định trong AOSP :