리눅스 커널 디버깅 (ftrace)

🖥 시작하며

본래 Docker를 이용해서 macOS에서 커널 디버깅을 수행하려고 했지만, 여러 문제가 겹치며 그냥 가상머신을 사용하는 것으로 가닥이 잡혔다.

이전 릴리스

🔍 Dockerfile과 대략적인 디버깅 방법

Dockerfile 작성


FROM --platform=linux/amd64 ubuntu:22.04

ENV DEBIAN_FRONTEND=noninteractive

# sources.list 파일을 카카오 미러 서버로 변경
RUN sed -i 's/archive.ubuntu.com/mirror.kakao.com/g' /etc/apt/sources.list

# QEMU와 커널 빌드를 위한 필수 패키지 설치
RUN apt-get update && apt-get install -y \
    binutils \
    build-essential \
    flex \
    bison \
    libssl-dev \
    libelf-dev \
    bc \
    libncurses5-dev \
    qemu-system-x86 \
    qemu-user-static \
    gdb-multiarch \
    vim \
    wget \
    gnupg \
    dwarves \
    zstd \
    cpio \
    busybox-static \
    trace-cmd \
    && rm -rf /var/lib/apt/lists/*

WORKDIR /kernel-source

# 커널 6.8.1 소스 다운로드
RUN wget https://cdn.kernel.org/pub/linux/kernel/v6.x/linux-6.8.1.tar.xz \
    && tar xf linux-6.8.1.tar.xz \
    && mv linux-6.8.1/* . \
    && rm -rf linux-6.8.1 linux-6.8.1.tar.xz

# 커널 설정 및 빌드
RUN make defconfig && \
    echo "CONFIG_BLK_DEV_INITRD=y" >> .config && \
    echo "CONFIG_DEBUG_INFO=y" >> .config && \
    echo "CONFIG_GDB_SCRIPTS=y" >> .config && \
    echo "CONFIG_KGDB=y" >> .config && \
    echo "CONFIG_KGDB_SERIAL_CONSOLE=y" >> .config && \
    echo "CONFIG_FTRACE=y" >> .config && \
    echo "CONFIG_FUNCTION_TRACER=y" >> .config && \
    echo "CONFIG_GENERIC_CPU=y" >> .config && \
    echo "CONFIG_X86_GENERIC=y" >> .config && \
    echo "CONFIG_DEBUG_PAGEALLOC=y" >> .config && \
    echo "CONFIG_PREEMPT=y" >> .config && \
    echo "CONFIG_RCU_NOCB_CPU=n" >> .config && \
    echo "CONFIG_DEBUG_FS=y" >> .config && \
    echo "CONFIG_TRACING=y" >> .config && \
    echo "# CONFIG_X86_AMD_PLATFORM_DEVICE is not set" >> .config && \
    echo 'CONFIG_DRM_I915=n' >> .config && \
    echo 'KBUILD_CFLAGS += -save-temps=obj -Wno-error' >> Makefile && \
    make olddefconfig && \
    make -j$(nproc) bzImage

# initramfs 생성
RUN mkdir -p initramfs && \
    cd initramfs && \
    mkdir -p bin dev etc proc sys/kernel/debug && \
    cp /bin/busybox bin && \
    ln -s busybox bin/sh && \
    ln -s busybox bin/mount && \
    ln -s busybox bin/echo && \
    echo '#!/bin/sh' > init && \
    echo 'mount -t proc none /proc' >> init && \
    echo 'mount -t sysfs none /sys' >> init && \
    echo 'mount -t debugfs none /sys/kernel/debug' >> init && \
    echo 'exec /bin/sh' >> init && \
    chmod +x init && \
    find . | cpio -o -H newc | gzip > ../initramfs.cpio.gz && \
    cd ..



# 부팅 스크립트 수정
RUN echo '#!/bin/bash' > /boot-kernel.sh && \
    echo 'qemu-system-x86_64 -cpu qemu64 -kernel arch/x86/boot/bzImage \
    -initrd initramfs.cpio.gz \
    -append "console=ttyS0 root=/dev/ram rdinit=/init nokaslr ftrace=function_noinit" \
    -s -S \
    -nographic' >> /boot-kernel.sh && \
    chmod +x /boot-kernel.sh


CMD ["/bin/bash"]

각 줄 설명


FROM --platform=linux/amd64 ubuntu:22.04

ENV DEBIAN_FRONTEND=noninteractive

# sources.list 파일을 카카오 미러 서버로 변경
RUN sed -i 's/archive.ubuntu.com/mirror.kakao.com/g' /etc/apt/sources.list

# QEMU와 커널 빌드를 위한 필수 패키지 설치
RUN apt-get update && apt-get install -y \
    binutils \
    build-essential \
    flex \
    bison \
    libssl-dev \
    libelf-dev \
    bc \
    libncurses5-dev \
    qemu-system-x86 \
    qemu-user-static \
    gdb-multiarch \
    vim \
    wget \
    gnupg \
    dwarves \
    zstd \
    cpio \
    busybox-static \
    trace-cmd \
    && rm -rf /var/lib/apt/lists/*

WORKDIR /kernel-source

# 커널 6.8.1 소스 다운로드
RUN wget https://cdn.kernel.org/pub/linux/kernel/v6.x/linux-6.8.1.tar.xz \
    && tar xf linux-6.8.1.tar.xz \
    && mv linux-6.8.1/* . \
    && rm -rf linux-6.8.1 linux-6.8.1.tar.xz

# 커널 설정 및 빌드
RUN make defconfig && \
    echo "CONFIG_BLK_DEV_INITRD=y" >> .config && \
    echo "CONFIG_DEBUG_INFO=y" >> .config && \
    echo "CONFIG_GDB_SCRIPTS=y" >> .config && \
    echo "CONFIG_KGDB=y" >> .config && \
    echo "CONFIG_KGDB_SERIAL_CONSOLE=y" >> .config && \
    echo "CONFIG_FTRACE=y" >> .config && \
    echo "CONFIG_FUNCTION_TRACER=y" >> .config && \
    echo "CONFIG_GENERIC_CPU=y" >> .config && \
    echo "CONFIG_X86_GENERIC=y" >> .config && \
    echo "CONFIG_DEBUG_PAGEALLOC=y" >> .config && \
    echo "CONFIG_PREEMPT=y" >> .config && \
    echo "CONFIG_RCU_NOCB_CPU=n" >> .config && \
    echo "CONFIG_DEBUG_FS=y" >> .config && \
    echo "CONFIG_TRACING=y" >> .config && \
    echo "# CONFIG_X86_AMD_PLATFORM_DEVICE is not set" >> .config && \
    echo 'CONFIG_DRM_I915=n' >> .config && \
    echo 'KBUILD_CFLAGS += -save-temps=obj -Wno-error' >> Makefile && \
    make olddefconfig && \
    make -j$(nproc) bzImage

# initramfs 생성
RUN mkdir -p initramfs && \
    cd initramfs && \
    mkdir -p bin dev etc proc sys/kernel/debug && \
    cp /bin/busybox bin && \
    ln -s busybox bin/sh && \
    ln -s busybox bin/mount && \
    ln -s busybox bin/echo && \
    echo '#!/bin/sh' > init && \
    echo 'mount -t proc none /proc' >> init && \
    echo 'mount -t sysfs none /sys' >> init && \
    echo 'mount -t debugfs none /sys/kernel/debug' >> init && \
    echo 'exec /bin/sh' >> init && \
    chmod +x init && \
    find . | cpio -o -H newc | gzip > ../initramfs.cpio.gz && \
    cd ..



# 부팅 스크립트 수정
RUN echo '#!/bin/bash' > /boot-kernel.sh && \
    echo 'qemu-system-x86_64 -cpu qemu64 -kernel arch/x86/boot/bzImage \
    -initrd initramfs.cpio.gz \
    -append "console=ttyS0 root=/dev/ram rdinit=/init nokaslr ftrace=function_noinit" \
    -s -S \
    -nographic' >> /boot-kernel.sh && \
    chmod +x /boot-kernel.sh


CMD ["/bin/bash"]

수정된 Dockerfile로 이미지를 빌드:


docker build -t kernel-debug-6.8.1 .

빌드가 완료되면 컨테이너를 실행:


docker run --name kernel-debug-container-6.8.1 \
  --platform linux/amd64 \
  -v "$(pwd)":/app \
  -w /kernel-source \
  -it \
  --cap-add=SYS_PTRACE \
  --security-opt seccomp=unconfined \
  --privileged \
  -p 4444:4444 \
  -p 5555:5555 \
  -p 6666:6666 \
  kernel-debug-6.8.1

컨테이너 내부에서 커널 소스 수정:


vim kernel/fork.c

kernel_clone 함수에 다음 라인을 추가:


printk(KERN_ALERT "안녕하세요\n");

수정된 커널 재컴파일:


make -j$(nproc) bzImage

컨테이너 내부에서 커널 부팅:


/boot-kernel.sh

새 터미널 창에서 컨테이너에 접속:


docker exec -it kernel-debug-container-6.8.1 /bin/bash

GDB 실행 (컨테이너 내부에서):


gdb-multiarch vmlinux

GDB에서 QEMU에 연결:


(gdb) target remote localhost:1234

커널 실행 시작:


(gdb) continue

명령어로 메시지를 확인:


dmesg | grep "안녕하세요"

만약 메시지가 보이지 않는다면, 새 프로세스를 생성하여 kernel_clone을 트리거:


echo "Hello"

그리고 다시 dmesg | grep "안녕하세요"를 실행한다.

13. ftrace 활성화


echo function > /sys/kernel/debug/tracing/current_tracer
echo 1 > /sys/kernel/debug/tracing/tracing_on

QEMU를 종료하려면 Ctrl+A, 그 다음 x를 누른다.

1️⃣ 가상머신 설치

ubuntu-22.04.5-live-server-arm64.iso 파일로 가상머신을 실행한 후, VS Code에서 ssh 환경으로 진행했다.

아래는 기본 설정이다.


sudo passwd root

sudo apt update
sudo apt install build-essential vim openssh-server net-tools

sudo systemctl enable ssh
sudo systemctl start ssh

sudo vi /etc/ssh/sshd_config

ifconfig

쉘 스크립트 파일을 생성하고, 실행시킨다.


chmod +x compile_kernel.sh
./compile_kernel.sh

# 혹은
bash compile_kernel.sh


#!/bin/bash
set -e  # 오류 발생 시 스크립트 중지

# 진행 상황을 출력하는 함수
function echo_progress {
    echo "=============================="
    echo "$1"
    echo "=============================="
}

# 필요한 패키지 설치
echo_progress "필요한 패키지 설치 중..."
sudo apt update
sudo apt install -y build-essential libncurses-dev bison flex libssl-dev libelf-dev wget

# 커널 소스 다운로드
echo_progress "커널 소스 다운로드 중..."
wget https://cdn.kernel.org/pub/linux/kernel/v6.x/linux-6.8.1.tar.xz
tar xf linux-6.8.1.tar.xz
cd linux-6.8.1

# 빌드 환경 정리
echo_progress "이전 빌드 아티팩트 정리 중..."
make clean
make mrproper

# 기본 설정
echo_progress "기본 커널 설정 적용 중..."
make defconfig

# ftrace 활성화를 위한 커널 설정 적용
echo_progress "ftrace 활성화를 위한 커널 설정 적용 중..."
scripts/config --enable CONFIG_FTRACE
scripts/config --enable CONFIG_DYNAMIC_FTRACE
scripts/config --enable CONFIG_FUNCTION_TRACER
scripts/config --enable CONFIG_FUNCTION_GRAPH_TRACER
scripts/config --enable CONFIG_IRQSOFF_TRACER
scripts/config --enable CONFIG_SCHED_TRACER
scripts/config --enable CONFIG_FUNCTION_PROFILER
scripts/config --enable CONFIG_STACK_TRACER
scripts/config --enable CONFIG_TRACER_SNAPSHOT

# 디버깅 및 코드 분석을 위한 추가 설정 적용
echo_progress "디버깅 및 코드 분석을 위한 설정 적용 중..."
scripts/config --enable CONFIG_DEBUG_INFO
scripts/config --enable CONFIG_DEBUG_INFO_DWARF4
scripts/config --enable CONFIG_GDB_SCRIPTS
scripts/config --enable CONFIG_KASAN
scripts/config --enable CONFIG_KASAN_INLINE
scripts/config --enable CONFIG_KCOV
scripts/config --enable CONFIG_PROVE_LOCKING
scripts/config --enable CONFIG_DEBUG_MUTEXES
scripts/config --enable CONFIG_DEBUG_SPINLOCK
scripts/config --enable CONFIG_DEBUG_ATOMIC_SLEEP
scripts/config --enable CONFIG_DETECT_HUNG_TASK
scripts/config --enable CONFIG_PANIC_ON_OOPS
scripts/config --enable CONFIG_SOFTLOCKUP_DETECTOR

# 설정 적용
echo_progress "설정 적용 중 (oldconfig)..."
make oldconfig

# 커널 컴파일
echo_progress "커널 컴파일 시작..."
make -j$(nproc)

# 모듈 설치
echo_progress "모듈 설치 중..."
sudo make modules_install

# 커널 설치
echo_progress "커널 설치 중..."
sudo make install

# initramfs 업데이트
echo_progress "initramfs 업데이트 중..."
sudo update-initramfs -c -k 6.8.1

# GRUB 설정 업데이트
echo_progress "GRUB 설정 업데이트 중..."
sudo update-grub

echo_progress "커널 컴파일 및 설치 완료."

직접 타이핑은 이걸로


#!/bin/bash

# 필요한 패키지 설치
sudo apt update
sudo apt install -y build-essential libncurses-dev bison flex libssl-dev libelf-dev

# 커널 소스 다운로드
wget https://cdn.kernel.org/pub/linux/kernel/v6.x/linux-6.8.1.tar.xz
tar xf linux-6.8.1.tar.xz
cd linux-6.8.1

# 기본 설정
make defconfig

# ftrace 활성화를 위한 커널 설정
echo "CONFIG_FTRACE=y" >> .config
echo "CONFIG_DYNAMIC_FTRACE=y" >> .config
echo "CONFIG_FUNCTION_TRACER=y" >> .config
echo "CONFIG_FUNCTION_GRAPH_TRACER=y" >> .config
echo "CONFIG_IRQSOFF_TRACER=y" >> .config
echo "CONFIG_SCHED_TRACER=y" >> .config
echo "CONFIG_FUNCTION_PROFILER=y" >> .config
echo "CONFIG_STACK_TRACER=y" >> .config
echo "CONFIG_TRACER_SNAPSHOT=y" >> .config

# 디버깅 및 코드 분석을 위한 추가 설정
echo "CONFIG_DEBUG_INFO=y" >> .config
echo "CONFIG_DEBUG_INFO_DWARF4=y" >> .config
echo "CONFIG_GDB_SCRIPTS=y" >> .config
echo "CONFIG_KASAN=y" >> .config
echo "CONFIG_KASAN_INLINE=y" >> .config
echo "CONFIG_KCOV=y" >> .config
echo "CONFIG_PROVE_LOCKING=y" >> .config
echo "CONFIG_DEBUG_MUTEXES=y" >> .config
echo "CONFIG_DEBUG_SPINLOCK=y" >> .config
echo "CONFIG_DEBUG_ATOMIC_SLEEP=y" >> .config
echo "CONFIG_DETECT_HUNG_TASK=y" >> .config
echo "CONFIG_PANIC_ON_OOPS=y" >> .config
echo "CONFIG_SOFTLOCKUP_DETECTOR=y" >> .config

# 커널 컴파일 
make -j$(nproc)

# 모듈 설치
sudo make modules_install

# 커널 설치
sudo make install

# initramfs 업데이트
sudo update-initramfs -c -k 6.8.1

# GRUB 설정 업데이트
sudo update-grub

💡

전체 전처리 수행 시 계속해서 오류가 나서 특정 부분만 그때그때 전처리 하는 방식으로 수정


make M=path/to/module modules
gcc -E path/to/module/source.c -o path/to/module/source.i

추가적으로 GRUB 도 로그인 때마다 선택창이 나오도록 설정했다.


# GRUB 열기
sudo nano /etc/default/grub

# 아래와 같이 수정
GRUB_TIMEOUT=10
GRUB_TIMEOUT_STYLE=menu
#GRUB_HIDDEN_TIMEOUT=0

# 변경사항 저장 후 재부팅
sudo update-grub
sudo reboot

커널 재컴파일은 아래와 같이 진행하면 된다.


# 커널 재컴파일
make -j$(nproc)

# 모듈 및 커널 설치
sudo make modules_install install

# initramfs 업데이트
sudo update-initramfs -c -k 6.8.1

# GRUB 설정 업데이트
sudo update-grub

VS Code에서 권한 주는 법


sudo visudo

# 맨 아래줄에 추가
usrname ALL=(ALL:ALL) NOPASSWD: ALL

# 폴더에 권한 추가
sudo chmod -R u+rwx /kernel
sudo chown -R reo:reo /kernel


# 관리자 쉘 진입
sudo -s

참고 사이트

ARM64 Mac UTM 에서 다른 아키텍처 설치 방법

유의 할 점 ARM64 가 아닌 CPU 아키텍처를 에뮬레이션 하는 경우, VM 자체 성능이 매우 느림을 감안하고 테스트 해야 합니다. 기본적인 설정들로만 x86_64 가상머신을 UTM을 통해 실행하려고 하면 각종 에러가 발생합니다. 아래 가이드에 맞게 실행하면 오류 없이 실행됩니다. Emulate 선택Linux 선택Boot ISO 이미지를 x86_64(amd64) 이미지로 선택따로 튜닝할 부분 없음. 기호에 맞게 메모리/CPU 코어 수정Open VM Settings 후 저장하여 VM 설정으로 이동CPU 를 기본 값에서 IvyBridge 로 변경 (변경하지 않으면 설치 단계에서 OS Installer 실행 시 glibc fatal error 발생)(참고 : How To Resolve Fatal glibc ..

https://madam.tistory.com/m/7

2️⃣ `ftrace` 란?

ftrace는 리눅스 커널에서 제공하는 강력한 디버그 툴로, 트레이싱 프레임워크다.

주로 성능 문제를 해결하거나 시스템 콜의 실행 과정을 분석할 때 사용한다. 또한 함수 호출, 인터럽트, 스케줄링 등 다양한 이벤트를 추적해 커널의 동작을 상세히 기록할 수 있도록 한다.

주요 기능은 다음과 같다:

함수 트레이싱 (Function Tracing): 커널 함수 호출을 추적하여 호출 순서 및 빈도를 파악할 수 있다.

이벤트 트레이싱 (Event Tracing): 특정 이벤트나 조건을 설정하여 커널에서 발생하는 특정 이벤트의 동작을 추적할 수 있다.

스케줄러 트레이싱 (Scheduler Tracing): 태스크 스케줄링 상황을 추적하여 프로세스의 상태 변화를 분석할 수 있다.

커스텀 트레이싱 (Custom Tracing): 사용자가 지정한 조건에 맞춰 원하는 함수나 이벤트를 트레이싱할 수 있다.

ftrace는 /sys/kernel/debug/tracing 경로를 통해 설정할 수 있으며, 커널에서 사용할 트레이서 종류나 필터를 설정하여 원하는 정보를 수집할 수 있다.


ls /sys/kernel/debug/tracing

>>>
available_events                  options                 stack_trace
available_filter_functions        per_cpu                 stack_trace_filter
available_filter_functions_addrs  printk_formats          timestamp_mode
available_tracers                 README                  touched_functions
buffer_percent                    saved_cmdlines          trace
buffer_size_kb                    saved_cmdlines_size     trace_clock
buffer_subbuf_size_kb             saved_tgids             trace_marker
buffer_total_size_kb              set_event               trace_marker_raw
current_tracer                    set_event_notrace_pid   trace_options
dynamic_events                    set_event_pid           trace_pipe
dyn_ftrace_total_info             set_ftrace_filter       trace_stat
enabled_functions                 set_ftrace_notrace      tracing_cpumask
error_log                         set_ftrace_notrace_pid  tracing_max_latency
events                            set_ftrace_pid          tracing_on
free_buffer                       set_graph_function      tracing_thresh
function_profile_enabled          set_graph_notrace       uprobe_events
instances                         snapshot                uprobe_profile
max_graph_depth                   stack_max_size

📌 `ftrace` 설정

다음과 같은 쉘 스크립트를 실행시켜 ftrace를 설정할 수 있다. 아래는 책의 예제다.


#!/bin/bash

# Ftrace 설정 스크립트

# Ftrace 일시 비활성화
echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1
echo "tracing_off"

# 모든 이벤트 비활성화
echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1
echo "events disabled"

# Ftrace 필터 설정
echo kernel_clone > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter init"

# Function 트레이서 활성화
echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"

# 특정 이벤트 활성화
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable

echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable

echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
sleep 1
echo "events enabled"

# 추가 Ftrace 필터 설정
echo schedule > /sys/kernel/debug/tracing/set_ftrace_filter

sleep 1
echo "set_ftrace_filter enabled"

# 스택 트레이스 옵션 설정
echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"

# Ftrace 최종 활성화
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"

echo "Ftrace setup complete"

Ftrace 비활성화


echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1
echo "tracing_off"

Ftrace를 일시적으로 비활성화한다. /sys/kernel/debug/tracing/tracing_on 파일에 0을 쓰면 현재 활성화된 추적이 중지된다. 이후 1초 동안 대기하여 변경 사항이 적용될 시간을 확보한다.

모든 이벤트 비활성화


echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1
echo "events disabled"

모든 추적 이벤트를 비활성화한다. /sys/kernel/debug/tracing/events/enable 파일에 0을 쓰면 현재 활성화된 모든 이벤트가 중지된다.

Ftrace 필터 설정


echo kernel_clone > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter init"

Ftrace 필터를 설정하여 특정 함수만 추적하도록 한다. set_ftrace_filter 파일에 kernel_clone을 쓰면 해당 함수에 대한 추적이 활성화된다.

여기서 set_ftrace_filter 파일에 필터로 함수를 지정하지 않으면 모든 가능한 함수를 트레이싱하다 시스템이 락업되버리니, 꼭 지정해야 한다.

Function 트레이서 활성화


echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"

함수 기반의 트레이서를 활성화한다. current_tracer 파일에 function을 설정함으로써 함수 호출에 대한 추적이 시작된다.

nop : 기본 트레이서, ftrace 이벤트만 출력

function : 함수 트레이서, set_ftrace_filter로 지정한 함수를 누가 호출했는지 출력

function_graph : 함수 실행 시간과 세부 호출 정보를 그래프 포맷으로 출력

특정 이벤트 활성화


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

echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable

echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
sleep 1
echo "events enabled"

여러 특정 이벤트를 활성화하여 보다 세부적인 추적이 가능하도록 설정한다.

sched_wakeup, sched_switch는 스케줄링 관련 이벤트이고,

irq_handler_entry, irq_handler_exit는 IRQ 핸들러의 진입과 종료를 추적하며,

raw_syscalls는 시스템 콜을 추적한다.

각 이벤트의 enable 파일에 1을 쓰면 해당 이벤트가 활성화된다.

추가 Ftrace 필터 설정


echo schedule > /sys/kernel/debug/tracing/set_ftrace_filter

sleep 1
echo "set_ftrace_filter enabled"

추가적인 Ftrace 필터를 설정하여 더욱 구체적인 함수에 대한 추적을 가능하게 한다. set_ftrace_filter 파일에 schedule을 추가함으로써 이 함수에 대한 추적이 활성화된다.

스택 트레이스 옵션 설정


echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"

스택 트레이스와 심볼 오프셋 옵션을 활성화하여 함수 호출의 스택 트레이스를 상세히 추적할 수 있도록 설정한다. func_stack_trace와 sym-offset 옵션 파일에 1을 쓰면 스택 트레이스와 심볼 오프셋이 활성화된다.

Ftrace 최종 활성화


echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"

echo "Ftrace setup complete"

모든 설정이 완료된 후 Ftrace를 최종적으로 활성화하여 추적을 시작한다. tracing_on 파일에 1을 쓰면 Ftrace가 활성화된다.

💡 추가 설정 파일들

buffer_size_kb

ftrace 로그의 버퍼 크기이며, 킬로바이트 단위이다. ftrace 로그를 담아 저장하고 싶을 때 설정한다.

available_filter_functions

트레이싱할 수 있는 함수 목록을 지정한 파일. 리눅스 드라이버나 커널에 새로운 함수를 새로 구현했으면 이 파일에 새로 작성한 함수 이름을 넣을 수 있다.

events

ftrace에서 제공하는 이벤트의 종류를 알 수 있는 디렉터리. 수많은 이벤트 중 가장 대표적인 부분 기술한다.

sched: 프로세스가 스케줄링되는 동작과 스케줄링 프로파일링을 트레이싱하는 이벤트들을 볼 수 있다.

sched_switch: 컨텍스트 스위칭 동작
sched_wakeup: 프로세스를 깨우는 동작

irq: 인터럽트와 Soft IRQ를 트레이싱하는 이벤트 존재

💡

Soft IRQ(Software Interrupt Reqeust)는 리눅스 커널에서 사용되는, 하드웨어 인터럽트의 상위 절반을 처리한 후 나머지 작업을 소프트웨어적으로 처리하는 메커니즘이다. 네트워크 패킷 처리나 타이머 함수, 블록 디바이스 I/O 완료 처리 등에 사용한다고 한다.

irq_handler_entry: 인터럽트가 발생한 시간과 인터럽트 번호 및 이름을 출력
irq_handler_exit: 인터럽트 핸들링이 완료
softirq_raise: Soft IRQ 서비스 실행 요청
softirq_entry: Soft IRQ 서비스 실행 시작
softirq_exit: Soft IRQ 서비스 실행 완료

⚙️ 실습용 `ftrace` 쉘


#!/bin/bash

# ============================
# 변수 설정 부분
# ============================

# 로그 저장 디렉토리 설정
LOG_DIR="./logs"

# 추적 기간 설정 (초 단위)
TRACE_DURATION=1

# 추적할 함수 이름 설정
FUNCTION_FILTER="do_exit"

# 함수가 존재하는지 확인 : sudo cat /sys/kernel/debug/tracing/available_filter_functions | grep "do_exit"

# ============================
# Ftrace 설정 함수
# ============================

setup_ftrace() {
    echo "Ftrace 설정을 시작합니다..."

    # Ftrace 일시 비활성화
    echo 0 > /sys/kernel/debug/tracing/tracing_on
    sleep 1
    echo "트레이싱 꺼짐"

    # 모든 이벤트 비활성화
    echo 0 > /sys/kernel/debug/tracing/events/enable
    sleep 1
    echo "이벤트 비활성화"

    # Ftrace 필터 설정 (특정 함수만 추적)
    echo "$FUNCTION_FILTER" > /sys/kernel/debug/tracing/set_ftrace_filter
    sleep 1
    echo "set_ftrace_filter 초기화: $FUNCTION_FILTER"

    # Function 트레이서 활성화
    echo function > /sys/kernel/debug/tracing/current_tracer
    sleep 1
    echo "트레이서 활성화: function"

    # 특정 이벤트 활성화
    # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
    # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable

    # echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
    # echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable

    # echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
    sleep 1
    echo "특정 이벤트 활성화"

    # 스택 트레이스 옵션 설정
    echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
    echo 1 > /sys/kernel/debug/tracing/options/sym-offset
    echo "스택 트레이스 활성화"

    # Ftrace 최종 활성화
    echo 1 > /sys/kernel/debug/tracing/tracing_on
    echo "트레이스 활성화"

    echo "Ftrace 설정이 완료되었습니다."
}

# ============================
# Ftrace 종료 및 로그 수집 함수
# ============================

collect_logs() {
    echo "Ftrace 추적을 종료합니다..."

    # Ftrace 비활성화
    echo 0 > /sys/kernel/debug/tracing/tracing_on
    echo "추적을 끝냅니다"

    # 로그 파일 수집
    cp /sys/kernel/debug/tracing/trace "$LOG_DIR"

    # tmp.log 파일 이름 결정
    LOG_FILE="$LOG_DIR/tmp.log"
    if [ -f "$LOG_FILE" ]; then
        counter=1
        while [ -f "${LOG_FILE%.*}_$counter.${LOG_FILE##*.}" ]; do
            ((counter++))
        done
        LOG_FILE="${LOG_FILE%.*}_$counter.${LOG_FILE##*.}"
    fi
    mv "$LOG_DIR/trace" "$LOG_FILE"
    echo "$LOG_FILE 에서 로그 확인이 가능합니다."

    # 그래프 함수 및 트레이서 초기화
    echo > /sys/kernel/debug/tracing/set_graph_function
    echo nop > /sys/kernel/debug/tracing/current_tracer
    echo "필터와 설정을 초기화했습니다."

    # 트레이싱 로그 삭제
    echo > /sys/kernel/debug/tracing/trace
    echo "트레이싱 로그를 삭제합니다."
}

# ============================
# 메인 로직
# ============================

main() {
    # 로그 디렉토리 생성
    mkdir -p "$LOG_DIR"

    # Ftrace 설정 및 시작
    setup_ftrace

    echo "Ftrace가 $TRACE_DURATION 초 동안 실행됩니다..."
    sleep "$TRACE_DURATION"

    # Ftrace 종료 및 로그 수집
    collect_logs

    echo "Ftrace 추적 및 로그 수집이 완료되었습니다."
}

# ============================
# 스크립트 실행
# ============================

main

📌 스택 트레이스, 심볼 오프셋 on/off 차이

💬 ON


# tracer: function
#
# entries-in-buffer/entries-written: 22/22   #P:6
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
           which-4674    [004] .....  3397.560610: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
           which-4674    [004] .....  3397.560612: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
              sh-4673    [001] .....  3397.561054: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
              sh-4673    [001] .....  3397.561060: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
              ps-4676    [001] .....  3397.608000: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
              ps-4676    [001] .....  3397.608001: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
              sh-4675    [004] .....  3397.608594: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
              sh-4675    [004] .....  3397.608595: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
             sed-4679    [002] .....  3397.624064: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
             sed-4679    [002] .....  3397.624067: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
             cat-4680    [005] .....  3397.628334: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
             cat-4680    [005] .....  3397.628348: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
             cat-4681    [002] .....  3397.632254: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
             cat-4681    [002] .....  3397.632255: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
             cat-4682    [005] .....  3397.634674: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
             cat-4682    [005] .....  3397.634674: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
             cat-4683    [003] .....  3397.636467: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
             cat-4683    [003] .....  3397.636468: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
             cat-4684    [000] .....  3397.638249: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
             cat-4684    [000] .....  3397.638249: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198
           sleep-4672    [003] .....  3398.555280: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218
           sleep-4672    [003] .....  3398.555293: <stack trace>
 => do_exit+0x8/0x1e00
 => do_group_exit+0xac/0x218
 => __arm64_sys_exit_group+0x44/0x58
 => invoke_syscall+0x74/0x268
 => el0_svc_common.constprop.0+0xb0/0x240
 => do_el0_svc+0x4c/0x70
 => el0_svc+0x50/0xa0
 => el0t_64_sync_handler+0x13c/0x158
 => el0t_64_sync+0x190/0x198


# 분석

	cat-4682 [005] ..... 3397.634674: do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218 
	cat-4682 [005] ..... 3397.634674: <stack trace> 
=> do_exit+0x8/0x1e00 
=> do_group_exit+0xac/0x218 
=> __arm64_sys_exit_group+0x44/0x58 
=> invoke_syscall+0x74/0x268 
=> el0_svc_common.constprop.0+0xb0/0x240 
=> do_el0_svc+0x4c/0x70 
=> el0_svc+0x50/0xa0 
=> el0t_64_sync_handler+0x13c/0x158 
=> el0t_64_sync+0x190/0x198

cat-4682: 실행 중인 프로세스 이름(cat)과 PID(4682)

[005]: 이 이벤트가 CPU 5에서 발생

3397.634674: 이벤트 발생 시간 (부팅 후 3397.634674초)


do_exit+0x4/0x1e00 <-do_group_exit+0xac/0x218

do_exit+0x4/0x1e00:

do_exit 함수의 시작 주소에서 0x4 바이트 떨어진 위치에서 호출이 발생했음을 의미한다.

/0x1e00는 함수의 전체 크기를 나타낸다. 이 때 단위는 바이트다.

<-do_group_exit+0xac/0x218:

do_group_exit 함수 내의 0xac 바이트 지점에서 do_exit 함수가 호출되었음을 의미한다.

/0x218는 do_group_exit 함수의 전체 크기다.


// do_group_exit 함수
void do_group_exit() {
		// ...

    // 0xac 바이트 지점에서 do_exit 함수 호출
    do_exit();

    // ...
}

// do_exit 함수
void do_exit() {
    // ... 함수 시작 지점에서 +0x4 바이트 지점부터 실행 ...
}

이후 각 함수명 뒤의 +0x오프셋/전체크기 는 해당 함수 내에서 호출이 발생한 위치와 함수 전체 크기를 나타낸다.

보기 쉬운 예시..


// el0t_64_sync 함수
void el0t_64_sync() {
    // ...

    el0t_64_sync_handler();
}

// el0t_64_sync_handler 함수
void el0t_64_sync_handler() {
    // ...

    el0_svc();
}

// el0_svc 함수
void el0_svc() {
    // ...

    do_el0_svc();
}

// do_el0_svc 함수
void do_el0_svc() {
    // ...

    el0_svc_common_constprop_0();
}

// el0_svc_common_constprop_0 함수
void el0_svc_common_constprop_0() {
    // ...

    invoke_syscall();
}

// invoke_syscall 함수
void invoke_syscall() {
    // ...

    __arm64_sys_exit_group();
}

// __arm64_sys_exit_group 함수
void __arm64_sys_exit_group() {
    // ...

    do_group_exit();
}

// do_group_exit 함수
void do_group_exit() {
    // ...

    do_exit();
}

// do_exit 함수
void do_exit() {
    // 프로세스 종료 처리
}

즉 이 로그는 el0t_64_sync에서 시작하여 do_group_exit 내에서 do_exit 함수를 호출함으로써, cat 프로세스가 종료된 것으로 보인다.

💡

사용자 공간, 즉 cat에서 exit() 호출하면 시스템 콜인 el0t_64_sync를 호출, 위로 스택 쌓여서 do_exit 호출?

💬 OFF


# tracer: function
#
# entries-in-buffer/entries-written: 14/14   #P:6
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
           sleep-4755    [000] ...1.  3414.570036: do_exit <-do_group_exit
             sed-4757    [005] ...1.  3414.579393: do_exit <-do_group_exit
             cat-4758    [002] ...1.  3414.588445: do_exit <-do_group_exit
     cpuUsage.sh-4759    [003] ...1.  3414.591183: do_exit <-do_group_exit
             cat-4760    [002] ...1.  3414.596231: do_exit <-do_group_exit
     cpuUsage.sh-4761    [005] ...1.  3414.598625: do_exit <-do_group_exit
             cat-4762    [002] ...1.  3414.604054: do_exit <-do_group_exit
     cpuUsage.sh-4763    [003] ...1.  3414.606408: do_exit <-do_group_exit
             cat-4764    [002] ...1.  3414.610936: do_exit <-do_group_exit
     cpuUsage.sh-4765    [001] ...1.  3414.612813: do_exit <-do_group_exit
     cpuUsage.sh-4766    [003] ...1.  3414.614736: do_exit <-do_group_exit
     cpuUsage.sh-4748    [004] ...1.  3414.615310: do_exit <-do_group_exit
              sh-4747    [001] ...1.  3414.615893: do_exit <-do_group_exit
           sleep-4756    [003] ...1.  3414.740638: do_exit <-do_group_exit

3️⃣ `ftrace` 메세지 분석 방법

🔍 `sched_switch` 이벤트 로그


# 보기 편하도록 줄바꿈 했음
kworker/u4:6-67 
[001] 
d..2.   
884.209885: 
sched_switch: 
prev_comm=kworker/u4:6 prev_pid=67 prev_prio=120 prev_state=R+ 
==> 
next_comm=sudo next_pid=1246 next_prio=120

우선 ftrace의 공통 포맷은 아래와 같다.


[작업명-PID] [CPU번호] [컨텍스트 플래그] [타임스탬프]: [이벤트 이름]: [이벤트 세부 정보]

이를 기반으로 위 코드를 분석해보자.

kworker/u4:6-67:

kworker/u4:6: 현재 실행 중인 프로세스 이름. 커널 워커 스레드인 듯 하다.

67: 이 프로세스의 PID

[001]:

이벤트가 발생한 CPU 번호. CPU 1에서 발생했다.

d..2.:

트레이스 옵션 플래그:

d: 인터럽트가 비활성화된 상태
. (n) : 현재 프로세스가 선점 스케줄링될 수 있는 상태가 아님
. (h/s) : 하드 또는 소프트 인터럽트 상태가 아님
2 (0 ~ 3): preempt_count 활성화
. : 특별한 상태 없음

좀 더 자세히 설명하자면, 이 구간은 컨텍스트 정보를 나타내며 아래와 같은 내용이 담긴다.

인터럽트 활성화/비활성화 여부

선점 스케줄링 설정 여부

인터럽트 컨텍스트나 Soft IRQ 컨텍스트 여부

프로세스의 thread_info 구조체의 preempt_count 값

884.209885:

이벤트 발생 시간 (초 단위)

sched_switch:

발생한 이벤트의 이름. 스케줄러 스위치 이벤트이다.

이벤트 세부 정보:

prev_comm=kworker/u4:6: 이전 작업의 이름 (커널 워커 스레드)

prev_pid=67: 이전 프로세스의 PID

prev_prio=120: 이전 프로세스의 우선순위

prev_state=R+: 이전 프로세스의 상태 (R은 실행 가능 상태, +는 추가 상태 플래그)

==>: 스위치 표시

next_comm=sudo: 다음 작업의 이름 (sudo 명령)

next_pid=1246: 다음 프로세스의 PID

next_prio=120: 다음 프로세스의 우선순위

즉 이 로그은 CPU 1에서 커널 워커 스레드(kworker/u4:6)에서 sudo 프로세스로 스케줄 전환이 일어났음을 보여준다. 커널 워커는 실행 가능한 상태(R+)에서 중단되었고, sudo 프로세스가 실행을 시작했다. 이는 시스템에서 사용자가 sudo 명령을 실행했거나, sudo에 의해 관리되는 작업이 스케줄되었음을 나타낸다.

4️⃣ `ftrace` 로 커널 내부 소스코드의 이벤트 출력 추적

ftrace는 ftrace 이벤트의 이름으로 커널 내부의 어떤 소스코드에서 이벤트를 출력하는지 알 수 있다.

예를 들어, sched_switch 이벤트는 trace_sched_switch 함수가 실행될 때 프로세스가 스케줄링되는 정보를 출력한다.


reo@reovm:/kernel/linux-6.8.1$ egrep -nr trace_sched_switch *


kernel/sched/core.c:6724: trace_sched_switch(sched_mode & SM_MASK_PREEMPT, prev, next, prev_state);

직접 소스코드를 타고 들어가보면 존재한다.

__schedule 함수의 6724번째 줄에서 ‘프로세스가 스케줄링하는 동작’을 출력한다는 사실을 알 수 있다. 이를 통해 컨텍스트 스위칭은 __schedule 함수에서 context_switch() 코드를 실행할 때 수행된다는 사실을 알 수 있다.

💡

이거 알아서 어디에 쓰는지 잘 모르겠습니다. 그냥 context switch 전에 스케줄링해서 context switch를 추적하는 건지, 그렇다면 그냥 추후 직접 추적하면 되는 게 아닌지 궁금합니다.

리눅스 커널 디버깅 (ftrace)

🖥 시작하며

🔍 Dockerfile과 대략적인 디버깅 방법

1️⃣ 가상머신 설치

2️⃣ ftrace 란?

📌 ftrace 설정

💡 추가 설정 파일들

⚙️ 실습용 ftrace 쉘

📌 스택 트레이스, 심볼 오프셋 on/off 차이

💬 ON

💬 OFF

3️⃣ ftrace 메세지 분석 방법

🔍 sched_switch 이벤트 로그

4️⃣ ftrace 로 커널 내부 소스코드의 이벤트 출력 추적