PintOS 프로젝트 수행 중 맞닥뜨렸던 에러를 핸들링하는 과정을 기록한 첫 번째 글이다.
문제 파악
멀티스레드의 대기(
wait) 상태를 요구하는 일부 테스트 케이스가 어떨 때는 통과되고 어떨 때는 실패함.
즉, 테스트 케이스의 시뮬레이션 결과가 랜덤하게 출력됨.
문제 발생 TEST CASE:
// parallel-merge.c
#include "tests/vm/parallel-merge.h"
#include <stdio.h>
#include <syscall.h>
#include "tests/arc4.h"
#include "tests/lib.h"
#include "tests/main.h"
#define CHUNK_SIZE (128 * 1024)
#define CHUNK_CNT 8 /* Number of chunks. */
#define DATA_SIZE (CHUNK_CNT * CHUNK_SIZE) /* Buffer size. */
unsigned char buf1[DATA_SIZE], buf2[DATA_SIZE];
size_t histogram[256];
/* Initialize buf1 with random data,
then count the number of instances of each value within it. */
static void
init (void)
{
struct arc4 arc4;
size_t i;
msg ("init");
arc4_init (&arc4, "foobar", 6);
arc4_crypt (&arc4, buf1, sizeof buf1);
for (i = 0; i < sizeof buf1; i++)
histogram[buf1[i]]++;
}
/* Sort each chunk of buf1 using SUBPROCESS,
which is expected to return EXIT_STATUS. */
static void
sort_chunks (const char *subprocess, int exit_status)
{
pid_t children[CHUNK_CNT];
size_t i;
for (i = 0; i < CHUNK_CNT; i++)
{
char fn[128];
char cmd[128];
int handle;
msg ("sort chunk %zu", i);
/* Write this chunk to a file. */
snprintf (fn, sizeof fn, "buf%zu", i);
create (fn, CHUNK_SIZE);
quiet = true;
CHECK ((handle = open (fn)) > 1, "open \"%s\"", fn);
write (handle, buf1 + CHUNK_SIZE * i, CHUNK_SIZE);
close (handle);
/* Sort with subprocess. */
snprintf (cmd, sizeof cmd, "%s %s", subprocess, fn);
children[i] = fork (subprocess);
if (children[i] == 0)
CHECK ((children[i] = exec (cmd)) != -1, "exec \"%s\"", cmd);
quiet = false;
}
for (i = 0; i < CHUNK_CNT; i++)
{
char fn[128];
int handle;
CHECK (wait (children[i]) == exit_status, "wait for child %zu", i);
/* Read chunk back from file. */
quiet = true;
snprintf (fn, sizeof fn, "buf%zu", i);
CHECK ((handle = open (fn)) > 1, "open \"%s\"", fn);
read (handle, buf1 + CHUNK_SIZE * i, CHUNK_SIZE);
close (handle);
quiet = false;
}
}
/* Merge the sorted chunks in buf1 into a fully sorted buf2. */
static void
merge (void)
{
unsigned char *mp[CHUNK_CNT];
size_t mp_left;
unsigned char *op;
size_t i;
msg ("merge");
/* Initialize merge pointers. */
mp_left = CHUNK_CNT;
for (i = 0; i < CHUNK_CNT; i++)
mp[i] = buf1 + CHUNK_SIZE * i;
/* Merge. */
op = buf2;
while (mp_left > 0)
{
/* Find smallest value. */
size_t min = 0;
for (i = 1; i < mp_left; i++)
if (*mp[i] < *mp[min])
min = i;
/* Append value to buf2. */
*op++ = *mp[min];
/* Advance merge pointer.
Delete this chunk from the set if it's emptied. */
if ((++mp[min] - buf1) % CHUNK_SIZE == 0)
mp[min] = mp[--mp_left];
}
}
static void
verify (void)
{
size_t buf_idx;
size_t hist_idx;
msg ("verify");
buf_idx = 0;
for (hist_idx = 0; hist_idx < sizeof histogram / sizeof *histogram;
hist_idx++)
{
while (histogram[hist_idx]-- > 0)
{
if (buf2[buf_idx] != hist_idx)
fail ("bad value %d in byte %zu", buf2[buf_idx], buf_idx);
buf_idx++;
}
}
msg ("success, buf_idx=%'zu", buf_idx);
}
void
parallel_merge (const char *child_name, int exit_status)
{
init ();
sort_chunks (child_name, exit_status);
merge ();
verify ();
}
// page-merge-par.c
#include "tests/main.h"
#include "tests/vm/parallel-merge.h"
void
test_main (void)
{
parallel_merge ("child-sort", 123);
}발생 원인
다음 우선순위 기부를 구현한 함수에서 if문 내부에서 실행되는 한 줄의 return 뒤를 주목해보면, 세미콜론 하나(!!!)를 빼먹었기 때문에 다음 줄의 코드가 그대로 이어붙여지면서 의도와 다른 실행으로 이어졌다.
//! 우선순위 기부
void
donate_priority (struct lock *lock) {
enum intr_level old_level;
struct thread *curr = thread_current ();
struct thread *holder = lock->holder;
if (holder != NULL) {
curr->wait_on_lock = lock;
if (curr->priority <= holder->priority) //* priority donate
return // <-- 세미콜론을 빼먹은 곳
old_level = intr_disable ();
holder->priority = curr->priority;
list_insert_ordered(&holder->donations, &curr->d_elem, cmp_priority_donation, NULL);
nest_donate (curr, lock, depth_max); //* priority donate nestly
intr_set_level (old_level);
}
}의도했던 실행:
if (curr->priority <= holder->priority) return; old_level = intr_disable (); // ...현재 실행중인 스레드의 우선순위가 락을 획득중인 스레드보다 우선순위가 낮은 경우 우선순위 기부를 실행하지 않아도 되므로
donate_priority함수를 곧바로 리턴하고 그렇지 않은 경우intr_disable함수를 호출.
실제 실행:
if (curr->priority <= holder->priority) return old_level = intr_disable ();현재 실행중인 스레드의 우선순위가 락을 획득중인 스레드보다 우선순위가 낮은 경우
intr_disable함수를 호출하면서donate_priority함수를 곧바로 리턴.
*여기서 intr_disable 함수는 현재 실행중인 스레드가 임계 영역에 진입하기 전에 경쟁 조건(race condiotion) 문제를 예방하기 위해 인터럽트 신호를 차단하도록 만드는 함수다. 또한 임계 영역에서의 작업을 처리한 후 리턴받았던 old_level 변수가 가진 상태로 인터럽트 상태를 반드시 되돌려 놓아야 한다. 하지만 위 경우 세미콜론 하나를 빼먹었기 때문에 인터럽트를 되돌려 놓지 않은 상태 그대로 리턴된다.
즉 문제의 if문에 들어가게 되는 특수한 경우, 인터럽트 신호를 차단한 상태 그대로 프로세스가 실행된다는 건데, 이는 이후의 작업 동안 컨텍스트 스위칭에 필요한 인터럽트 신호를 무시하겠다는 소리이므로 멀티스레딩 자체가 작동하지 않는다.
해결 방법과 사후 처리
세미콜론을 붙여 해결했다. ¯＼＿(ツ)＿/¯
하지만 고전적인 C 컴파일러, 바보같은 세미콜론 실수와 더불어 어설픈 코드 컨벤션이 만든(자그마치 3개의 재앙이 만들어낸 대환장 트러블슈팅) 실수라고 판단하여,
PintOS 팀원들에게 if문이나 for문, while문 내에서 실행하는 코드가 1줄로 끝나더라도 반드시 중괄호{}를 추가해야 한다는 코드 컨벤션을 제안했다. 그렇게 한다면 C 컴파일러가 이런 세미콜론을 하나 빼먹은 실수도 쉽게 잡아내기 때문이다.
제안 전:
if (curr->priority <= holder->priority) return old_level = intr_disable ();앞서 말했듯이 c 컴파일러가
if (curr->priority <= holder->priority) return old_level = intr_disable ();와 같은 한 줄로 읽어버리며 아무 에러도 잡아주지 않음.
제안 후:
if (curr->priority <= holder->priority) { return } old_level = intr_disable ();c 컴파일러가
expected an expression에러를 띄워줌.
에러 핸들링 과정
1. 에러 로그 확인
Kernel panic in run: PANIC at ../../devices/timer.c:201 in real_time_sleep(): assertion 'intr_get_level () == INTR_ON' failed.
지금 확인해보면 상당히 직관적으로 에러를 짚어주고 있지만, intr 함수와 관련된 에러들이 이전 Page Fault 에러 핸들링 과정에서 intr 관련 코드를 수정하지 않고 해결되었던 적이 많아 핸들링 방향성을 섣불리 정하지 못하고 헤맸다.
먼저 테스트 케이스의 결과가 랜덤하게 바뀌는 것에 주목하여 테스트 케이스 코드에서 랜덤 시드 사용 여지가 있었는지 파악했다..만 주어진 테스트 케이스 코드에서는 랜덤의 ra자도 보이지 않았다.
2. 테스트 케이스의 에러 발생 시점 색출
콜스택 에러 로그:
debug_panic (lib/kernel/debug.c:32)
real_time_sleep (devices/timer.c:202)
timer_nsleep (devices/timer.c:128)
select_device (devices/disk.c:503)
select_device_wait (devices/disk.c:511)
select_sector (devices/disk.c:415)
disk_read (devices/disk.c:220)
inode_open (filesys/inode.c:129)
dir_open_root (filesys/directory.c:49)
filesys_create (filesys/filesys.c:63)
create (userprog/syscall.c:223)
syscall_handler (userprog/syscall.c:84)
no_sti (userprog/syscall-entry.o:?)위 테스트케이스는 약 1MB의 무작위 데이터를 생성한 후 16개의 청크로 분할한다. 각 청크는 메인 프로세스에서 fork시킨 하위 프로세스에서 정렬되며, 이 하위 프로세스들은 병렬적으로 실행된다.
위 콜스택 로그를 확인해봤을 때, wait 관련 함수(select_device_wait)에서 호출하는 timer_nsleep에서 항상 인터럽트 신호가 꺼져있는 상황이 발생했다는 것이다. 신기한 것은 16개의 하위 프로세스는 이 wait 관련 함수를 일관적으로 호출하는데, ＊4~7번째로 실행되는 프로세스까지 와서야 wait 관련 함수에서 문제가 발생했다는 것이다. (＊4~7: 실행마다 달랐음)
즉 어느정도 하위 프로세스가 fork되어 스케줄링된 스레드가 서로 경쟁을 시작할 때 쯤에 wait 관련 함수에서 문제가 발생했다는 것이다.
3. 트러블 발생 지역 축소
여기까지 알아냈지만 도저히 원인을 찾아낼 수 없어서 한 가지 편법을 썼다.
사실 문제의 테스트 케이스 page-merge-par은 이전 커밋 기록에서 이미 통과했던 케이스였다. 문제가 되는 지역을 축소하기 위해서 용의자가 될 만한 파일을 추려내고, 통과했던 커밋 기록의 같은 파일을 다시 붙여넣어(그림자 밟기) 테스트를 시뮬레이션했다.
아니나 다를까, 위 donate_priority 함수가 있는 threads/synch.c 파일이 문제였다. 거기서 다시 차근차근 분석해보니 if 문 내의 한 줄 return 뒤에 세미콜론이 지워졌다는 것을 찾아내게 되었다.
4. 비고
이렇게 정답지를 보고 나니, 결과가 랜덤하게 출력되던 이유와 에러 발생 시점이 이해되기 시작했다. 나노초 단위로 갱신되는 스레드의 우선순위가 아다리가 맞아 현재 실행중인 스레드의 우선순위가 락을 획득중인 스레드보다 우선순위가 낮은 경우를 단 한번도 만나지 않으면 운이 좋게도(?🤬) 통과가 된다. 그리고 그런 경우가 나오기 위해서는 멀티 프로세스가 병렬적으로 진행되면서 스레드들끼리 경쟁하기 시작하여야 한다.
범인은 코드 한 줄도 아닌 세미콜론 단 한 문자 때문이라는 것을 뼈저리게 통감했으며 이런 문제를 예방하는 방법에 대해 고찰할 수 있었다..
