[리눅스 커널] debug - dynamic debug

글의 참고

-  https://www.kernel.org/doc/html/v5.0/admin-guide/dynamic-debug-howto.html

---

글의 전제

- 밑줄로 작성된 글은 강조 표시를 의미한다.

- 그림 출처는 항시 그림 아래에 표시했다.

---

글의 내용

: 리눅스 커널에서 `pr_deug`나 `dev_dbg`는 dmesg에 출력되지 않는다. 해당 함수들을 통해서 로그를 출력하려면 한 가지 조건이 필요하다.

 

현재 동작하는 커널에 CONFIG_DYNAMIC_DEBUG 가 설정되어 있어야 한다.

 

 

: 현재 동작중인 커널 CONFIG를 확인해보고 싶다면, `zcat /proc/config.gz | grpe -i DYNAMIC*` 을 통해 확인이 가능하다. 설정이 되어있지 않다면, `${ARCH}_defconfig` 파일에 `CONFIG_DYNAMIC_DEBUG`를 추가하고 다시 빌드해야 한다.

 

: 빌드 후, 커널을 시작하고 쉘을 통해 `동적 로깅`이 가능한지 확인할 수 있다. `동적 로깅`이 활성화되면, 쉘에서  `/sys/kernel/debug/dynamic_debug/` 폴더를 확인할 수 있다. 거기에서 `control` 파일이 중요하다. 아마, `cat control` 명령어를 실행해보면, 엄청난 양의 로그들을 볼 수 있을 것이다. 그 내용들이 전부 `pr_debug`, `dev_dbg` 함수를 사용한 로그들이다. 우리가 원하는 로그를 활성화, 즉, 출력시키기 위해서는 먼저 `grep`을 통해 자기가 보고 싶은 함수를 필터해야 한다. 예시를 통해 알아보자.

 

: 내가 만든 `RTC 드라이버`가 insmod만 하면 dmesg에 아래와 같은 로그들이 출력됬다.

[ 1113.671375] ds1307 1-0068: registered as rtc0
[ 1113.675262] ds1307 1-0068: hctosys: unable to read the hardware clock
[ 1143.521538] ds1307 1-0068: registered as rtc0
[ 1143.526267] ds1307 1-0068: hctosys: unable to read the hardware clock

: `로그`가 발생하는 루틴을 찾기 위해 커널 소스 레벨에서 원인을 찾아봤다.

 

/drivers/rtc/class.c - v5.10.103

#ifdef CONFIG_RTC_HCTOSYS_DEVICE
/* Result of the last RTC to system clock attempt. */
int rtc_hctosys_ret = -ENODEV;

/* IMPORTANT: the RTC only stores whole seconds. It is arbitrary
 * whether it stores the most close value or the value with partial
 * seconds truncated. However, it is important that we use it to store
 * the truncated value. This is because otherwise it is necessary,
 * in an rtc sync function, to read both xtime.tv_sec and
 * xtime.tv_nsec. On some processors (i.e. ARM), an atomic read
 * of >32bits is not possible. So storing the most close value would
 * slow down the sync API. So here we have the truncated value and
 * the best guess is to add 0.5s.
 */

static void rtc_hctosys(struct rtc_device *rtc)
{
	int err;
	struct rtc_time tm;
	struct timespec64 tv64 = {
		.tv_nsec = NSEC_PER_SEC >> 1,
	};

	err = rtc_read_time(rtc, &tm);
	if (err) {
		dev_err(rtc->dev.parent,
			"hctosys: unable to read the hardware clock\n");
		goto err_read;
	}

	tv64.tv_sec = rtc_tm_to_time64(&tm);

#if BITS_PER_LONG == 32
	if (tv64.tv_sec > INT_MAX) {
		err = -ERANGE;
		goto err_read;
	}
#endif

	err = do_settimeofday64(&tv64);

	dev_info(rtc->dev.parent, "setting system clock to %ptR UTC (%lld)\n",
		 &tm, (long long)tv64.tv_sec);

err_read:
	rtc_hctosys_ret = err;
}
#endif

: `rtc_read_time` 함수에서 에러가 나서 발생하는 문제로 보인다. 그래서 `rtc_read_time`함수를 확인해봤다.

 

/drivers/rtc/interface.c - v5.10.103

static int __rtc_read_time(struct rtc_device *rtc, struct rtc_time *tm)
{
	int err;

	if (!rtc->ops) {
		err = -ENODEV;
	} else if (!rtc->ops->read_time) {
		err = -EINVAL;
	} else {
		memset(tm, 0, sizeof(struct rtc_time));
		err = rtc->ops->read_time(rtc->dev.parent, tm);
		if (err < 0) {
			dev_dbg(&rtc->dev, "read_time: fail to read: %d\n",
				err);
			return err;
		}

		rtc_add_offset(rtc, tm);

		err = rtc_valid_tm(tm);
		if (err < 0)
			dev_dbg(&rtc->dev, "read_time: rtc_time isn't valid\n");
	}
	return err;
}

int rtc_read_time(struct rtc_device *rtc, struct rtc_time *tm)
{
	int err;

	err = mutex_lock_interruptible(&rtc->ops_lock);
	if (err)
		return err;

	err = __rtc_read_time(rtc, tm);
	mutex_unlock(&rtc->ops_lock);

	trace_rtc_read_time(rtc_tm_to_time64(tm), err);
	return err;
}
EXPORT_SYMBOL_GPL(rtc_read_time);

 

: rtc_read_time() 은 동기화 기법만 사용하기 위한 껍데기이고, 실제 기능은 `__rtc_read_time` 함수에서 수행한다. 결국, `__rtc_read_time` 함수에서 로그를 출력하는지가 궁금해졌고, 로그를 출력한다면 2개의 로그 중 어떤 로그가 출력되는지 궁금해졌다. 

 

: 먼저 `cat control | grpe -i __rtc_read_time` 을 확인해보자. 해당 명령어를 통해 `__rtc_read_time` 함수가 동적 로깅을 사용하는지 알 수 있다. 

root@raspberrypi:/sys/kernel/debug/dynamic_debug# cat control | grep -i "__rtc_read_time"
drivers/rtc/interface.c:97 [rtc_core]__rtc_read_time =p "read_time: fail to read: %d\012"
drivers/rtc/interface.c:105 [rtc_core]__rtc_read_time =p "read_time: rtc_time isn't valid\012"

: 이 함수를 enable하게 되면 로그들이 dmesg에 출력 될 것 이다.

 

echo "func __rtc_read_time +p" > control

 

: `func` 은 함수를 의미하며, 인자는 함수명을 쓰고 `+p`는 flags로 `동적 로깅`을 활성화 한다는 것을 의미한다. 이제 sudo insmod ds1307.ko 를 입력하면 dmesg에 아래와 같이 출력된다. `동적 로깅`으로 작성된 함수들의 로그가 출력되는 것을 볼 수 있다.

[ 1113.671375] ds1307 1-0068: registered as rtc0
[ 1113.675262] ds1307 1-0068: hctosys: unable to read the hardware clock
[ 1143.521538] ds1307 1-0068: registered as rtc0
[ 1143.526267] ds1307 1-0068: hctosys: unable to read the hardware clock
[ 1530.219146] rtc rtc0: read_time: rtc_time isn't valid
[ 1530.219966] ds1307 1-0068: registered as rtc0
[ 1530.222872] rtc rtc0: read_time: rtc_time isn't valid
[ 1530.222886] ds1307 1-0068: hctosys: unable to read the hardware clock
[ 1897.727730] rtc rtc0: read_time: rtc_time isn't valid

 

: rtc_valid_time() 함수에서 에러가 발생한 것을 알 수 있다. 참고로, `동적 로깅`은 다양한 포맷들을 지원한다. 위 예시는 `__rtc_read_time` 함수내에 존재하는 `동적 로깅`만 활성화했다. 그런데, 하나의 파일에서 사용되는 모든 `동적 로깅`을 보고 싶은 경우가 있을 것이다. 혹은, LKM 모듈에서 사용하는 `동적 로깅`을 보고 싶은 경우도 있을 것이다. 해당 내용들은 이 글을 참고하자.

 

- Dynamic Debug on Boot

: 부팅 시점에 `Dynamic Debug`는 확인이 가능할까? 가능하다. 빌트-인 모듈이라면, `커널 커맨드 라인 파라미터`에 `dyndbg=<QUERY>`를 작성하면 된다. 여기서 `<QUERY>`는 "func __rtc_read_time +p" 다이내믹 디버그 포맷을 의미한다.