Sử dụng ftrace

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

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

Ghi lại các sự kiện nhân bằng dấu vết

atrace (frameworks/native/cmds/atrace) sử dụng ftrace để thu thập sự kiện nhân hệ điều hành. Đổi lại, systrace.py (hoặc run_systrace.py trong các phiên bản sau này của Catapult) sử dụng adb để chạy Atrace trên thiết bị. atrace thực hiện những việc sau:

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

Ngoại trừ tính năng theo dõi thời gian khởi động, hãy sử dụng dấu vết để đặt thành giá trị thích hợp. Cơ sở lưu trú có mặt nạ hơi và không có gì tốt giúp xác định các giá trị chính xác ngoài việc xem xét tiêu đề phù hợp (có thể thay đổi giữa các bản phát hành Android).

Bật sự kiện ftrace

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

Để bật sự kiện theo từng danh mục, hãy sử dụng: 

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

Để bật sự kiện theo 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 bật bằng cách ghi vào các nút sysfs, chúng sẽ không bị dấu vết đặt lại. Một mẫu chung cho việc hiển thị thiết bị Qualcomm là bật kgsl (GPU) và mdss (quy trình hiển thị) điểm theo dõi và 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 có atrace hoặc systrace, hữu ích khi bạn muốn các dấu vết chỉ dành cho nhân hệ điều hành (hoặc nếu bạn đã dành thời gian để ghi thuộc tính theo dõi ở chế độ người dùng theo cách thủ công). Cách chỉ chạy ftrace:

  1. Đặt dung lượng bộ nhớ đệ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. Bật tính năng theo dõi: 
    echo 1 > /sys/kernel/tracing/tracing_on
  3. Chạy kiểm thử, 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

Dấu vết_đầu ra cung cấp dấu vết ở dạng văn bản. Cách trực quan hoá dữ liệu bằng cách sử dụng Máy bắn đá, lấy Satapult kho lưu trữ từ GitHub và chạy trace2html:

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

Theo mặc định, lệnh này sẽ ghi trace_file.html trên cùng một thư mục.

Liên hệ sự kiện

Thường rất hữu ích khi xem hình ảnh Máy bắn đá và đường cong ghi nhật ký đồng thời; ví dụ: một số sự kiện ftrace (đặc biệt là sự kiện dành riêng cho nhà cung cấp ) không được Catapult hình dung. Tuy nhiên, dấu thời gian của Catapult liên quan đến sự kiện đầu tiên trong dấu vết hoặc dấu thời gian cụ thể được kết xuất bởi atrace, trong khi dấu thời gian ftrace thô dựa trên nguồn xung nhịp tuyệt đối trong nhân Linux.

Cách tìm một sự kiện ftrace nhất định trong một sự kiện Catapult:

  1. Mở nhật ký ftrace thô. Các dấu vết trong các phiên bản systrace gần đây là nén theo mặc định:
    • Nếu bạn đã ghi lại systrace bằng --no-compress, thì giá trị này nằm trong tệp html trong phần bắt đầu bằng BEGIN TRACE.
    • Nếu không, hãy chạy html2trace từ Satapult cây (tracing/bin/html2trace) để giải nén dấu vết.
  2. Tìm dấu thời gian tương đối trong hình ảnh Máy bắn.
  3. Tìm một dòng ở đầu dấu vết có chứa tracing_mark_sync. Hàm này có dạng như sau: 
    <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 không có dấu vết), thì thời gian sẽ là tương đối từ 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ị trong parent_ts (tính bằng giây).
    2. Tì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) với sự kiện.

Sử dụng ftrace động

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

Để bật ftrace động, hãy chỉnh sửa cấu hình defconfig của hạt nhân:

  1. Xoá CONFIG_STRICT_MEMORY_RWX (nếu có). Nếu bạn đang dùng phiên bản 3.18 hoặc phiên bản mới hơn và arm64 thì không.
  2. Thêm đường dẫn sau: CONFIG_dynamic_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y và CONFIG_PREEMPT_TRACER=y
  3. Tạo lại và khởi động nhân hệ điều hành mới.
  4. Chạy lệnh sau để kiểm tra các trình theo dõi hiện có: 
    cat /sys/kernel/tracing/available_tracers
  5. Xác nhận rằng lệnh sẽ trả về function, irqsoff, preemptoff và preemptirqsoff.
  6. Chạy lệnh 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 tất các bước này, bạn sẽ có ftrace động, trình phân tích hàm, trình phân tích tài nguyên irqsoff và trình phân tích tài nguyên có sẵn. Chúng tôi mạnh mẽ nên đọc tài liệu về ftrace về các chủ đề này trước khi sử dụng vì chúng mạnh mẽ nhưng phức tạp. irqsoff và Preemptoff chủ yếu hữu ích khi xác nhận rằng người lái xe có thể đang bị gián đoạn hoặc giành quyền tắt quá lâu.

Trình phân tích hàm là lựa chọn tốt nhất cho các vấn đề về hiệu suất và thường dùng để tìm ra nơi một hàm sẽ được gọi.

Trong vấn đề này, việc sử dụng Pixel XL để chụp ảnh HDR+ thì sau đó ngay lập tức việc xoay kính ngắm thường gây ra hiện tượng giật. Chúng ta đã sử dụng trình phân tích hàm để gỡ lỗi trong vòng chưa đầy một giờ. Tiếp theo, tải tệp zip xuống của các dấu vết (cũng có thể bao gồm các dấu vết khác được đề cập trong phần này), hãy giải nén tệp và mở 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 quá trình cameraserver bị chặn trong chế độ ngủ không gián đoạn trên ion_client_destroy. Như vậy là đắt đỏ nhưng nên gọi rất hiếm khi xảy ra vì ứng dụng ion nên bao gồm nhiều đối tượng phân bổ. Ban đầu, lỗi thuộc về mã lục giác ở Halide, chính là một trong những thủ phạm (nó đã tạo ra một khách hàng mới cho mỗi phân bổ ion và huỷ bỏ ứng dụng đó khi quá trình phân bổ đã được giải phóng. Điều này quá tốn kém). Chuyển sang một ứng dụng ion duy nhất cho tất cả Hình lục giác các quá trình phân bổ đã cải thiện tình hình, nhưng hiện tượng giật chưa được khắc phục.

Tại thời điểm này, chúng tôi cần biết ai đang gọi ion_client_destroy, vì vậy, đây là lúc sử dụng trình phân tích hàm:

  1. Vì các hàm đôi khi được trình biên dịch đổi tên, hãy xác nhận ion_client_destroy ở đó 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 thẻ này ở đó, 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 phân tích hàm: 
    echo function > /sys/kernel/tracing/current_tracer
  4. Bật dấu vết ngăn xếp mỗi khi hàm lọc được gọi: 
    echo func_stack_trace > /sys/kernel/tracing/trace_options
  5. Tăng dung lượng bộ nhớ đệm: 
    echo 64000 > /sys/kernel/tracing/buffer_size_kb
  6. Bật tính năng theo dõi: 
    echo 1 > /sys/kernel/tracing/trace_on
  7. Chạy chương trình kiểm thử và nhận dấu vết: 
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace
  8. Xem dấu vết để thấy 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 một hàm không gian người dùng đang đóng một fd đến /dev/ion, không phải là trình điều khiển nhân ngẫu nhiên. Bằng cách tìm kiếm Cơ sở mã Android dành cho \"/dev/ion\", chúng tôi tìm thấy một số trình điều khiển của nhà cung cấp thực hiện tương tự như trình điều khiển hình lục giác và mở/đóng /dev/ion (tạo và huỷ một ứng dụng ion mới) mỗi khi chúng cần phân bổ ion mới. Thay đổi các cài đặt đó thành sử dụng một ứng dụng ion duy nhất trong suốt thời gian hoạt động của quy trình đã khắc phục được lỗi này.

Nếu dữ liệu từ trình phân tích hàm không đủ cụ thể, bạn có thể kết hợp loại bỏ các điểm theo dõi bằng trình phân tích hàm. có thể bật sự kiện ftrace trong chính xác 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 rất phù hợp nếu thỉnh thoảng có một giấc ngủ dài không gián đoạn trong một mà bạn muốn gỡ lỗi: đặt bộ lọc ftrace thành hàm bạn muốn, bật điểm theo dõi, ghi lại dấu vết. 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 đó nhận dấu vết ngăn xếp ở gần trong dấu vết thô.

Sử dụng chế độ khoá

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

Tuy nhiên, Lockstat sử dụng quy trình gỡ lỗi cơ sở hạ tầng khóa, điều này hữu ích đối với nhiều ứng dụng khác. Mọi người khi xử lý quá trình khởi động thiết bị sẽ tìm ra cách để làm cho tuỳ chọn đó hoạt động trên mọi thiết bị vì sẽ có lúc bạn nghĩ rằng "Nếu chỉ có thể bật LOCK_STAT, tôi có thể xác nhận hoặc bác bỏ ý kiến này chỉ trong năm phút thay vì năm ngày".

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

Chúng tôi đã đưa ra giả thuyết rằng chính ftrace là nguồn gốc của tranh chấp khoá, khi một luồng có mức độ ưu tiên thấp sẽ bắt đầu ghi vào ống ftrace rồi nhận bị chặn trước trước khi nó có thể mở khoá. Đây là trường hợp xấu nhất mà trở nên trầm trọng hơn do việc kết 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ị đã tải hoàn chỉnh.

Vì không thể dùng ftrace để gỡ lỗi nên LOCK_STAT đã hoạt động sau đó 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 khoá tranh chấp thực sự xuất phát từ ftrace vì không có tranh chấp nào xuất hiện trong dấu vết khoá khi ftrace không chạy.

Nếu bạn có thể khởi động một nhân bằng tuỳ chọn config, thì tính năng theo dõi khoá sẽ tương tự như ftrace:

  1. Bật tính năng theo dõi: 
    echo 1 > /proc/sys/kernel/lock_stat
  2. Chạy chương trình kiểm thử.
  3. Tắt tính năng theo dõi: 
    echo 0 > /proc/sys/kernel/lock_stat
  4. Kết xuất 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 về khoá dữ liệu lúc <kernel>/Documentation/locking/lockstat.txt.

Sử dụng điểm theo dõi 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 cần phải sử dụng điểm theo dõi nhà cung cấp:

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

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

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

  • listCategory() tạo (vec<TracingCategory> danh mục);
  • enableCategory(vec<string> loại) sẽ tạo ra (Trạng thái);
  • vô hiệu hoáAllCategory() 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: