3.1 디버깅이란?
→ 버그를 수정하고 있다는 의미
→ 리눅스 커널과 드라이버가 정상 동작할 때 자료구조와 함수 호출 흐름까지 파악하는 과정
1) 문제 해결 능력의 지름길
커널 디버깅은 문제 해결 능력 그 자체이다.
※ 임베디드 리눅스 활용 분야
- 부팅 도중 커널 크래시 발생
- 인터럽트 핸들러를 설정했는데 호출되지 않음
- 시스템 응답 속도가 매우 느려짐
- 파일 복사가 안 됨
문제를 해결하기 위해서는 문제 발생의 원인을 분석해야 하고,
문제 발생의 원인은 문제 발생 시 확보한 커널 로그와 메모리 덤프를 정확히 분석해야 한다.
→ 임베디드 BSP 개발에서 커널 로그와 메모리 덤프를 정확히 분석하는 스킬을 ‘커널 디버깅’이라고 한다.
※ 리눅스 커널을 구성하는 서브시스템이 정상적으로 동작할 때 파악할 내용
- 함수가 실행될 때 변경되는 자료구조
- 함수가 실행되는 빈도와 실행 시각
- 실행 중인 코드를 어떤 프로세스가 실행하는지 확인
→ 프로그램이 정상적으로 동작할 때의 함수 호출 흐름과 자료구조를 알고 있어야 오류나 버그 발생 시 무엇이 문제인지 식별 가능하기 때문
★ 커널 로그 분석
① 오류 메시지를 커널의 어느 코드에서 출력했는지 확인
__enable_irq( ) 함수에서 오류 조건을 검출한 것으로 보이고, 어느 코드에서 콜 스택을 출력했는지 살펴봐야 함
irq_desc 구조체의 depth 필드는 인터럽트를 활성화하면 0, 비활성화하면 1을 설정
6번째 줄 코드는 인터럽트를 2번 활성화했을 때 실행되며 이미 인터럽트를 활성화했으면 depth 필드가 0인데 다시 활성화했기 때문에 콜 스택을 출력한다.
※ warn( ) 매크로 함수가 호출되면 커널 로그로 콜 스택을 출력한다.
② 소스코드에서 에러 메시지를 출력한 이유 살펴보기
IRQ 4 : 4번 인터럽트를 두 번 활성화했기 때문에 오류 발생
위 에러 메시지는 enable_irq( ) 함수에서 출력하는데 함수 내부에 있는 논리적 오류 때문이 아닌
enable_irq( ) 함수를 호출한 드라이버 코드에 있는 오류 때문일 가능성이 높다.
커널 에러 메시지를 보면 svsknfdrvr 드라이버 모듈이 보이고,
만약 enable_irq( ) 함수를 호출한 코드가 svsknfdrvr 드라이버 코드에 있다면 관련 코드를 분석한 후 논리적인 오류가 있는지 점검해야 함
③ 필요에 따라 디버깅 코드를 작성해 다시 문제가 발생했을 때 추가 커널 로그 확보 시도
패치 코드를 입력해 문제 현상을 재현하여 커널 로그를 받아보면 누가 4번 인터럽트를 2번 활성화했는지 알려줄 것이다.
__disable_irq ( ) 함수와 __ enable_irq( ) 함수의 2번째 인자는 인터럽트 번호를 나타내는 irq이다.
위 코드에서는 이 인터럽트 번호가 4일 때 콜 스택을 호출한다.
위 패치 코드를 빌드해서 시스템에 반영한 후 문제를 다시 재현하면 4번 인터럽트를 활성화 혹은 비활
성화할 때 콜스택을 커널 로그로 출력하여 어떤 코드에서 연속으로 활성화했는지 알아낼 수 있다.
2) 디버깅과 코드 학습 능력
디버깅을 하면서 리눅스 커널 코드를 함께 분석하면 다음과 같은 정보를 얻을 수 있다.
- 분석 대상 코드가 동작하는 콜 스택
- 함수가 실행될 때 변경되는 자료구조
- 함수가 실행되는 빈도와 실행 시각
- 분석 대상 코드를 실행하는 프로세스
★ 커널 디버깅 과정 예시
※ 명령어 "cat /proc/interrupts" : 인터럽트의 세부 속성
"/* 이 부분에 번째 패치 코드를 입력하세요 */＂라는 주석으로 표시된 부분에 다음 코드를 입력
irqaction 구조체 타입인 action 포인터형 변수가 NULL 이 아닐 때 action 인자와 함께 rpi_get_interrupt_info( ) 함수를 호출하는 코드
rpi_get_interrupt_info( ) 함수는 ftrace 로 다음 정보를 출력 하는 기능
- 프로세스 이름
- 인터럽트 번호
- 인터럽트 이름
- 인터럽트 핸들러 함수 이름
위와 같은 패치 코드를 입력한 이유는??
위와 같이 인터럽트의 속성 정보는 action 필드에 저장된다.
irqaction 구조체 오른쪽 부분에 표시된 주석이 인터럽트의 속성 정보이고,
이 정보를 라즈비안에서 확인하기 이해 패치 코드를 입력한 것이다.
echo rpi_get_interrupt_info > /sys/kernel/debug/tracing/set_ftrace_filter
패치 코드에서 작성한 rpi_get_interrupt_info( )라는 함수명을 /sys/kernel/debug/tracing/set_ftrace_filter 파일에 지정하는 명령어
→ rpi_get_interrupt_info( ) 함수를 누가 호출했는지 알 수 있음
./irq_trace_ftrace.sh : 셸 스크립트 실행
cat /proc/interrupts : rpi_get_interrupt_info( ) 함수가 호출되도록 커널을 동작시키는 역할
ftrace 로그를 라즈비안 시스템에서 안전하게 추출하기 위한 셸 스크립트 코드
./get_ftrace.sh : ftrace 로그가 현재 디렉터리에 복사되어 ftrace 로그를 확인할 수 있음
함수의 흐름은 11번째 줄에서 3번째 줄 방향으로 이어짐
01 : pid가 884인 cat 프로세스가 rpi_get_interrupt_info( ) 함수 호출
05 : seq_read( ) 함수에서 show_interrupts( ) 함수 호출
10 : sys_read( ) 함수가 호출된 후 유저 공간에서 read 시스템 콜 실행
egrep -nr irq_handler * : 현재 디렉토리에 있는 파일에서 irq_handler라는 문자열을 검색한 다음과 같은 결과 출력
- 인터럽트 번호
- 인터럽트 이름
- 인터럽트 핸들러 이름
ex)
- 인터럽트 번호 : 86
- 인터럽트 이름 : mmc1
- 인터럽트 핸들러 이름 : bcm2835 mmc_irq
3.2 printk( ) 함수
→ printk( ) 함수를 호출하면 커널 로그를 볼 수 있다.
위와 같이 레지스터 정보를 출력해준다.
▶ printk로 함수 심벌 정보를 보는 방법
- printk로 포인터를 출력하고 싶을 때는 %p를 쓰면 된다.
- %pS를 쓰면 함수 주소를 심벌로 출력한다. → 함수 포인터를 디버깅할 때 자주 쓰는 기법
- 리눅스 커널 코드에 printk 코드 입력해보기
08 : 프로세스 이름 출력
09~10
- __ func __ : 현재 실행 중인 함수의 이름
- __ LINE__: 현재 실행 중인 코드 라인
- _builtin_return_address(0): 현재 실행 중인 함수를 호출한 함수의 주소
빌드 후 설치하면 위와 같은 커널 로그를 볼 수 있고, 로그에 담긴 디버깅 정보는 다음과 같다.
- printk 로그를 실행한 포로세스의 이름은 kworker/2 : 3이다.
- printk가 추가된 곳은 insert_wq_barrier( ) 함수의 2354번째 줄이다.
- insert_wq_barrier( ) 함수는 workqueue_cpu_down_callback( ) 함수가 호출했다.
★ printk를 쓸 때 주의해야 할 점
→ printk의 호출 빈도를 반드시 체크해야 한다.
리눅스 커널에서 1초에 수백 번 이상 호출되는 함수에 printk를 사용하면 시스템이 락업되거나 커널 패닉으로 오동작할 수 있음
∵ printk가 커널 입장에서 많은 비용이 드는 함수이기 때문
락업 : 리눅스 디바이스에서 마우스를 움직이거나 키보드를 입력해도 아무런 반응이 없는 상황
3.3 dump_stack( ) 함수
→ 커널 로그를 통해 커널 동작을 보여주는 기능
▶ dump_stack( ) 함수 사용법
- "linux/kernel.h" 헤더 파일 추가하기
- asmlinkage __visible void dump_stack (void); 인자와 반환값 모두 void
▶ dump_stack( ) 함수로 커널 로그에서 콜 스택 확인하기
_do_fork( ) 함수 : 함수 콜 스택을 확인하기 위한 코드
01 : 콜 스택을 실행한 프로세스 정보
02~07 : 콜 스택
06 : sys_clone( ) 함수에서 _do_fork( ) 함수를 호출한다고 알려줌
함수 호출은 07번째 줄에서 03번째 줄 방향으로 이뤄짐
★ dump_stack( ) 함수를 쓸 때 주의해야 할 점
→ dump_stack( ) 함수를 호출하여 콜 스택을 보려는 코드가 자주 호출되는지 점검해야 함
dump_stack( )은 현재 실행 중인 프로세스 스택 주소를 읽어 스택에 푸시된 프레임 포인터 레지스터를 읽고,
ARM 아키텍처의 함수 호출 규약에 따라 프레임 포인터 레지스터를 읽어 함수 호출 내역을 추적하는 동작 반복
3.4 ftrace
→ 리눅스 커널에서 제공하는 강력한 디버그 기능
- 함수 호출 흐름을 소스코드를 수정하지 않고도 볼 수 있음
- 커널의 세부 실행 정보 출력
- 1초에 수십 번 호출해도 성능에 부담 없음
- 커널 로그 함께 볼 수 있음
※ ftrace의 특징
① 인터럽트, 스케줄링 커널 타이머 등의 커널 동작을 상세히 추적한다.
② 함수 필터를 지정하면 지정한 함수를 호출한 함수와 전체 콜 스택까지 출력하며 코드를 수정할 필요가 없다.
③ 함수를 어느 프로세스가 실행하는지 알 수 있다.
④ 함수가 실행된 시각 정보를 알 수 있다.
⑤ ftrace 로그를 활성화해도 시스템 동작에 부하를 거의 주지 않는다.
▶ ftrace 설정
/sys/kernel/debug/tracing에서 ftrace 설정 파일을 확인할 수 있다.
- sleep 1 : 1초 동안 딜레이를 주는 동작
- tracing_on : 트레이서 활성화
- tracer 설정
① nop : 기본 트레이서, ftrace 이벤트만 출력
② function : 함수 트레이서, set_ftrace filter로 지정한 함수를 누가 호출하는지 출력
③ function_graph : 함수 실행 시간과 세부 호출 정보를 그래프 포맷으로 출력
- set_ftrace_filter : 필터 설정
→ 리눅스 커널에 존재하는 모든 함수를 필터로 지정할 수는 없고, available_filter_functions 파일에 포함된 함수만 지정할 수 있음
▶ 추가 설정 파일
- buffer_size_kb : ftrace 로그의 버퍼 크기, 킬로바이트 단위, ftrace 로그를 더 많이 저장하고 싶을 때 설정
- available_filter_functions : 트레이싱할 수 있는 함수 목록을 저장한 파일
- events : ftrace에서 제공하는 이벤트의 종류를 알 수 있는 디렉터리
- sched : 프로세스가 스케줄링되는 동작과 스케줄링 프로파일링을 트레이싱하는 이벤트를 볼 수 있음
• sched_switch: 컨텍스토 스위칭 동작
• sched_wakeup: 프로세스를 우는 동작
- irq : 인터럽트와 Soft IRQ를 트레이싱하는 이벤트
• irq_handler_entry: 인터럽트가 발생한 시각과 인터럽트 번호 및 이름을 출력
• irq_handler_exit: 인터럽트 핸들링이 완료
• softirq_raise: Soft IRQ 서비스 실행 요청
• softirq_entry: Soft lRQ 서비스 실행 시작
• softirq_exit: Soft IRQ 서비스 실행 완료
▶ ftrace 로그 추출
./get_ftrace.sh로 셸 스크립트를 실행하면 같은 폴더에 ftrace 로그가 담긴 ftrace log.c 라는 파일이 생성됨
★ ftrace는 커널 코드 분석의 안내자이다.
→ ftrace 이벤트의 이름으로 커널 내부의 어떤 소스코드에서 이벤트를 출력하는지 알 수 있기 때문
3.5 임베디드 디버거의 전설 TRACE32
▶ 주소로 코드 정보 파악
▶ 전역 변수 확인
▶ 구조체를 주소로 캐스팅
▶ 어셈블리 코드 보기
'2021 SUMMER STUDY > LINUX KERNEL' 카테고리의 다른 글
| Week05_프로세스3 (0) | 2021.08.21 |
|---|---|
| Week04_프로세스2 (0) | 2021.08.15 |
| Week03_프로세스 (0) | 2021.08.09 |
| Week01_리눅스 소개와 전망 (0) | 2021.07.18 |