ftrace 사용

ftrace는 Linux 커널의 내부 상황을 이해하기 위한 디버깅 도구입니다. 다음 섹션에서는 ftrace 기능의 기본 정보, ftrace가 atrace(커널 이벤트를 캡처)와 함께 사용되는 방식, 그리고 동적 ftrace에 대해 상세히 설명합니다.

systrace에서 사용할 수 없는 고급 ftrace 기능에 대한 자세한 내용은 ftrace 문서(<kernel tree>/Documentation/trace/ftrace.txt)를 참조하세요.

atrace로 커널 이벤트 캡처

atrace(frameworks/native/cmds/atrace)는 ftrace를 사용하여 커널 이벤트를 캡처합니다. 따라서 systrace.py(또는 향후 Catapult 버전의 run_systrace.py)는 adb를 사용하여 기기에서 atrace를 실행합니다. atrace는 다음을 실행합니다.

  • 속성(debug.atrace.tags.enableflags)을 설정하여 사용자 모드 트레이싱을 설정합니다.
  • 원하는 ftrace 기능을 적절한 ftrace sysfs 노드에 작성하여 사용 설정합니다. 하지만 ftrace는 더 많은 기능을 지원하므로 직접 일부 sysfs 노드를 설정한 다음 atrace를 사용할 수도 있습니다.

부팅 시간 트레이싱을 제외하고는 atrace 사용에 의존하여 속성을 적절한 값으로 설정해야 합니다. 이 속성은 비트마스크이며 적절한 헤더(Android 버전 간에 변경될 수 있음)를 보는 것 말고는 정확한 값을 파악할 수 있는 좋은 방법이 없습니다.

ftrace 이벤트 사용 설정

ftrace sysfs 노드는 /sys/kernel/tracing에 있으며 트레이스 이벤트는 /sys/kernel/tracing/events에서 카테고리로 나뉩니다.

카테고리별 기준으로 이벤트를 사용 설정하려면 다음을 사용하세요. 

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

이벤트별 기준으로 이벤트를 사용 설정하려면 다음을 사용하세요. 

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

추가 이벤트가 sysfs 노드에 작성하여 사용 설정된 경우 atrace에 의해 재설정되지 않습니다. Qualcomm 기기를 불러오기 위한 일반적인 패턴은 kgsl(GPU) 및 mdss(디스플레이 파이프라인) tracepoint를 사용 설정한 다음 atrace 또는 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

또한 atrace 또는 systrace 없이도 ftrace를 사용할 수 있으며, 이는 커널 전용 트레이스를 원하거나 직접 사용자 모드 트레이싱 속성을 작성한 경우에 유용합니다. ftrace만 실행하는 방법:

  1. 버퍼 크기를 트레이스에 적합한 크기의 값으로 설정합니다. 
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
  2. 트레이싱을 사용 설정합니다. 
    echo 1 > /sys/kernel/tracing/tracing_on
  3. 테스트를 실행한 다음 트레이싱을 사용 중지합니다. 
    echo 0 > /sys/kernel/tracing/tracing_on
  4. 트레이스를 덤프합니다. 
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output

trace_output은 텍스트 형식의 트레이스를 제공합니다. Catapult를 사용하여 시각화하려면 GitHub에서 Catapult 저장소를 가져오고 trace2html을 실행합니다.

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

그러면 기본적으로 trace_file.html이 같은 디렉터리에 작성됩니다.

이벤트의 상관 관계 지정

Catapult 시각화와 ftrace 로그를 동시에 보면 유용할 때가 종종 있습니다. 예를 들면 일부 ftrace 이벤트(특히 공급업체별 이벤트)는 Catapult에 의해 시각화되지 않습니다. 하지만 Catapult의 타임스탬프는 트레이스의 첫 번째 이벤트나 atrace에 의해 덤프된 특정 타임스탬프를 기준으로 삼는 반면 원본 ftrace 타임스탬프는 Linux 커널의 특정 절대 클럭 소스에 기반합니다.

Catapult 이벤트에서 ftrace 이벤트를 찾는 방법:

  1. 원본 ftrace 로그를 엽니다. 최신 systrace 버전의 트레이스는 기본적으로 압축됩니다.
    • --no-compress로 systrace를 캡처한 경우 이는 BEGIN TRACE로 시작하는 섹션의 html 파일입니다.
    • 아니면 Catapult 트리(tracing/bin/html2trace)에서 html2trace를 실행하여 트레이스를 압축 해제합니다.
  2. Catapult 시각화에서 상대적 타임스탬프를 찾습니다.
  3. 트레이스 시작 부분에서 tracing_mark_sync를 포함하는 행을 찾습니다. 다음과 같이 표시됩니다. 
    <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286

    이 행이 존재하지 않거나 atrace 없이 ftrace를 사용한 경우에는 시점이 ftrace 로그의 첫 번째 이벤트와 상대적인 관계를 지니게 됩니다.
    1. parent_ts(초)의 값에 상대적 타임스탬프(밀리초)를 추가합니다.
    2. 새 타임스탬프를 검색합니다.

이러한 단계를 실행하면 이벤트에 도달하거나 적어도 아주 근접하게 됩니다.

동적 ftrace 사용

systrace 및 표준 ftrace가 부족한 경우에 사용 가능한 마지막 하나의 리소스가 있습니다. 바로 동적 ftrace입니다. 동적 ftrace를 사용하려면 부팅 이후에 커널 코드를 재작성해야 하므로, 결과적으로는 보안상의 이유로 프로덕션 커널에서 동적 ftrace를 사용할 수 없습니다. 하지만 2015년 및 2016년 이후의 모든 까다로운 성능 버그는 궁극적으로 동적 ftrace의 사용이 원인이었습니다. 이는 특히 무중단 절전 모드를 디버깅하는 경우에 강력함을 발휘합니다. 무중단 절전 모드를 트리거하는 함수를 실행할 때마다 커널에서 스택 트레이스를 가져오기 때문입니다. 또한 인터럽트 및 선점이 사용 중단된 섹션도 디버그할 수 있으며, 이는 문제를 증명하는 데 매우 유용합니다.

동적 ftrace를 켜려면 커널의 defconfig를 수정합니다.

  1. CONFIG_STRICT_MEMORY_RWX가 있으면 삭제합니다. 3.18 이상 및 arm64에는 없습니다.
  2. CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y 및 CONFIG_PREEMPT_TRACER=y를 추가합니다.
  3. 새 커널을 다시 빌드하고 부팅합니다.
  4. 다음을 실행하여 사용 가능한 트레이서가 있는지 확인합니다. 
    cat /sys/kernel/tracing/available_tracers
  5. 명령어가 function, irqsoff, preemptoff 및 preemptirqsoff를 반환하는지 확인합니다.
  6. 다음을 실행하여 동적 ftrace가 작동하는지 확인합니다. 
    cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>

이 단계를 완료하면 동적 ftrace, 함수 프로파일러, irqsoff 프로파일러 및 preemptoff 프로파일러를 보유하게 됩니다. ftrace는 강력하지만 복잡하기 때문에 사용 전에 관련 문서를 참조하는 것이 좋습니다. irqsoff 및 preemptoff는 드라이버가 인터럽트 또는 선점을 장시간 동안 꺼진 상태로 유지할 수 있는지를 확인하는 데 유용합니다.

함수 프로파일러는 성능 문제와 관련된 최선의 선택이며, 함수가 호출되고 있는 위치를 파악하는 데 자주 사용됩니다.

함수 프로파일러의 데이터가 충분히 구체적이지 않은 경우 ftrace tracepoint를 함수 프로파일러와 결합할 수 있습니다. ftrace 이벤트는 평상시와 동일한 방식으로 사용 설정할 수 있으며, 본인의 트레이스와 인터리브됩니다. 이는 디버그하려는 구체적인 함수에서 간혹 긴 시간 동안 무중단 절전 모드가 발생하는 경우에 유용하며, 원하는 함수에 ftrace 필터를 설정하고 tracepoint를 사용 설정한 다음 트레이스를 취하면 됩니다. 결과적으로 생성된 트레이스를 trace2html로 파싱하고 원하는 이벤트를 찾은 다음 원본 트레이스에서 근처의 스택 트레이스를 가져옵니다.

lockstat 사용

간혹 ftrace로는 충분하지 않고 커널 잠금 경합으로 보이는 문제를 디버그해야 할 때가 있습니다. 시도해볼 만한 커널 옵션이 하나 더 있습니다. 바로 CONFIG_LOCK_STAT입니다. 이 최후의 수단은 Android 기기에서 작동하도록 만들기가 무척 어려우며, 이는 대부분의 기기에서 처리할 수 없을 정도로 커널의 크기를 확장하기 때문입니다.

하지만 lockstat은 다른 수많은 애플리케이션에 유용한 디버그 잠금 인프라를 사용합니다. 기기를 불러오려는 사용자는 이 옵션이 모든 기기에서 작동하게 만들기 위한 방법을 찾아내야 합니다. LOCK_STAT만 켤 수 있다면 5일이 아닌 5분 안에 이를 문제로 확인하거나 반박할 수 있겠다는 생각이 들 때가 분명히 올 것이기 때문입니다.

구성 옵션으로 커널을 부팅할 수 있는 경우에는 잠금 트레이싱이 ftrace와 유사합니다.

  1. 트레이싱을 사용 설정합니다. 
    echo 1 > /proc/sys/kernel/lock_stat
  2. 테스트를 실행합니다.
  3. 트레이싱을 사용 중지합니다. 
    echo 0 > /proc/sys/kernel/lock_stat
  4. 트레이스를 덤프합니다. 
    cat /proc/lock_stat > /data/local/tmp/lock_stat

결과 해석에 도움이 필요한 경우 lockstat 문서(<kernel>/Documentation/locking/lockstat.txt)를 참고하세요.

공급업체 tracepoint 사용

업스트림 tracepoint를 먼저 사용해야 하지만 경우에 따라서는 공급업체 tracepoint를 사용해야 합니다.

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

tracepoint는 HAL 서비스로 확장 가능하며, 확장 시 기기별 tracepoint/카테고리를 추가할 수 있습니다. tracepoint는 perfetto, atrace/systrace 및 기기의 시스템 트레이싱 앱과 통합됩니다.

tracepoint/카테고리 구현을 위한 API는 다음과 같습니다.

  • listCategories()는 (vec<TracingCategory> categories)를 생성합니다.
  • enableCategories(vec<string> categories)는 (Status status)를 생성합니다.
  • disableAllCategories()는 (Status status)를 생성합니다.
자세한 내용은 AOSP의 HAL 정의 및 기본 구현을 참조하세요.