[pintos] prj1 출력 밀림 현상 발생 원인 찾기

Yejin Kim·2022년 10월 2일

OS Operating System pintos trouble shooting 트러블 슈팅

Pintos

목록 보기

1/2

🖨 출력 밀림 현상

사실 이 현상을 출력 밀림 현상이라고 해도 될지 모르겠지만 이 현상을 겪고 있는 많은 사람들이 이렇게 표현을 하니 나도 이렇게 표현을 해본다.

정확한 원인은 아직 모르지만 정답에서는 (exec-arg) end가 출력이 되어야 하는데 내 코드는 ((exec-arg) end가 출력이 되고 있음을 확인할 수 있다.

이 문제가 해결하기 골치 아픈 이유는 항상 이렇게 나오는 것이 아니라 언제는 정답(pass)으로 나오고 언제는 밀림 현상이 발생해서 실패(fail)이 뜨기 때문이다.

특히 해당 test case를 make check가 아니라
pintos -v -k -T 60 --qemu --filesys-size=2 -p tests/userprog/args-single -a args-single -- -q -f run 'args-single onearg'
와 같이 별도로 build 디렉토리 안에서 실행해주면 몇 번이고 정상적으로 출력이 된다. 🤦🏻‍♀️

이 문제가 시스템 상의 문제다, 코드 상의 문제다 의견이 분분했지만
몇 번이고 정상적으로 실행된다는 사람들이 있고, 조교님 또한 일단 확인해보았을 때 이런 현상이 발생하지 않는다는 답변을 주셔서 나도 시스템을 의심하지 않고 최대한 내 코드를 의심해보기로 하였다.

들어가기 전, 이 글은
내 코드의 문제인지 아닌지를 살펴보고
코드의 문제가 아니라는 판단이 들면, 그 판단에 대한 근거자료를 만들기 위한 글임을 알립니다.

코드 흐름 이해하기

baseline의 코드 flow부터 따라가 보기로 했다. 멀티 스레딩, 멀티 프로세싱의 경우 흐름을 놓치면 코드 자체를 이해할 수 없기 때문에 baseline의 전체적인 흐름을 톺아 보면 도움이 될 지도 .. ?

강의 자료를 들고 와 보았다...

main

가장 처음 실행되는 main 함수는 src/thread/init.c에 있다.
command_line을 읽어서 argv에 적절히 parsing을 하여 저장하는 것을 볼 수 있다.
여러가지 setting이 끝나고 main의 끝 부분에 run_actions가 있다. 이 친구가 우리가 생각하는 user program을 실행시켜 준다.

run_actions

run_actions는 main과 같은 파일에 구현되어 있다.

run_actions에서는 main으로 부터 받은 argv를 가지고 해당하는 action을 찾는다. action을 찾고 실행해야 하는 함수를 함수포인터(a->function(argv))를 통해 호출함으로써 실행을 시작한다.

prj1에서는 모든 애들을 run으로 돌리는 것 같다.
{"run", 2, run_task"}만 고려해서 디버깅 생각하면 될 듯 !

특히 나머지 ls, cat, rm.. 등은 #ifdef FILESYS ~ #endif로 감싸져 있는데 이는 FILESYS가 정의되어 있을 때만 실행을 하도록 하는 것이므로 아직까지는 해당 부분이 코드에 포함되지 않을 것으로 보인다.
현재 프로젝트에서는 #ifdef USERPROG ~ #endif만 신경쓰면 될 듯하다.

run_task

그러면 해당 코드는 function자리에 있는 run_task를 실행시키게 될 것이다. run_task도 같은 파일에 구현되어 있다. 현재 USERPROG가 정의되어 있어서 #ifdef USERPROG ~ #else 사이에 있는 process_wait(process_execute(task)); 만 실행이 된다.

과연 이 자리에서 밀림 현상이 발생하는 건지 테스트 해보기 위해 이 코드를 주석 처리하고 [123]을 출력하는 printf문을 넣어 돌려보았다.
당연히 정상적으로 프로그램을 실행시키지 않았기 때문에 FAIL이 뜨기는 하지만 밀림 현상은 여러번 실행을 해보아도 나타나지 않는다.

그렇다면 코드의 문제일 확률이 기하급수적으로 올라간다 😰

process_wait(process_execute(task))와 같이 실행을 시키면 어떤 함수에서 문제가 생기는 지 정확히 판단하기 어려우므로 다음과 같이 쪼개서 테스트를 해보고자 한다. 우선 process_wait을 주석 처리하고 돌려보자

어김없이 발생하는 밀림 현상... 🤬

process_execute

process_execute를 살펴보자..

여기서 핵심적인 부분은 thread를 start하는 것일 것이다. 이 thread를 생성하지 않고 돌려보자. 출력이 전혀 없으면 이런식으로 출력이 밀리는지 아닌지를 볼 수 없으므로 뭐라도 출력해본다. 역시나 thread loc은 아주 잘 하나씩 정상적으로 나온다.

start_process

생성시킨 thread는 start_process를 진행하게 되므로 이를 살펴보자. 기본적인 setting이 진행되고 load함수를 호출한다. load함수는 프로그램을 메모리에 적재해주는 함수이므로 메모리 적재가 완료된 후에 sema_up을 해주어 parent가 진행될 수 있도록 해주었다.

sema_up을 사이로 print를 진행해보자. sema_load는 메모리 적재에만 관여하는 semaphore이므로 thread 실행 자체에는 크게 관여하지 않는 듯 보인다. (여전히 밀림 현상도 나타나고 있는 것을 확인할 수 있다.)

아래 주석을 읽어 보면 모든 적재가 정상적으로 완료되고 나서 asm_volatile에 있는 어셈블리 코드를 통해 실질적으로 프로그램이 수행되는 것 같다.

asm_volatile 코드 아래에 sema_up을 넣어주는 경우에는 영원히 sema_up이 되지 않아 무한 대기 상태가 발생한다.
이것으로 보아 exec 계열 함수처럼 다시 이 함수로 돌아오지 않는 듯 보인다.
또한 그 아래에 NOT_REACHED 코드는 에러 처리 함수로, 어셈블리 코드가 정상 동작하지 않는 경우에만 해당 함수의 아랫부분을 실행하게 됨을 추측할 수 있다.

이 코드 이후에 syscall이 호출되는 것으로 보인다.

syscall_handler

위와 같이 출력 문을 넣고 돌려보자 출력 결과를 보면 매 line마다 system call! 이 붙어서 나오는 것을 볼 수 있다. 이 각 line은 어떤 syscall을 하는 것일까?
현재 STDOUT으로 결과를 보고 있으므로 아마 write 함수일 것이다. 맞는 지 한 번 putbuf를 주석 처리하고 돌려보자
역시나 그렇다...
write 함수 자체에서 buffer를 잘못 가지고 있는걸까? 확인해보자

write

...? string으로 하려니까 안되넹 ㅎ 안되겠다 hex_dump로 찍어보자
오... 제일 아래 보면 메모리 구조는 정상적으로 들어있는데 ( 하나가 더 끼어서 출력이 되고 있는 것을 알 수 있다. 대체 나한테 왜 이러는겨..

size가 잘못들어가고 있는지 size를 출력하도록 하고 다시 실행해보자
?! 지금
(create-bound) end
는 문자 18개에 마지막에 0a(LF)까지 총 19개가 맞다.
즉, size도 잘 들어옴 ❗️
buffer도 정상이고 size도 정상이고 그 상태로 putbuf에 넘겨만 줬을 뿐인데 뜬금 없이 (c 가 앞에 끼어든...?

후... 한 5시간 디버깅 했는데 여기서 포기할 순 없지... 🔥
putbuf 보자.. 젠장

putbuf

src/lib/kernel에 구현되어 있네요
음... 일단 buffer, n 잘 들어왔을 거고 lock도 잡는 것 같네요
내부적으로 lock걸고 putchar 하나 봅니다.

putchar_have_lock 도 들어가보자
오...
putchar_have_lock에서 결국 최종적으로 write을 해주는 것 같다.
putbuf에서 잡은 console lock때문에 여기서 printf를 해주면 무한 룹이 발생하니까 putbuf에서 lock을 acquire 하기 전에 print로 찍어보자
기존 출력과 구분 짓기 위해 비교 출력은 앞에 ------ 문자열을 붙여준다.
......???? buffer를 n개 연속으로 찍으면 (exec-multiple) end가 잘 나오는데 왜 console에는 (e가 붙어서 나오는거죠?

결국 putchar_have_lock을 뜯어봐야 하는 것인가 ... 😱

보니까 vga_putc는 white space 등을 화면에 출력하기 위한 함수로 보인다.

그럼 얘가 문자 전부 찍어주는 것 같다.
여기서 polling이 하나의 장치(또는 프로그램)가 충돌 회피 또는 동기화 처리 등을 목적으로 다른 장치(또는 프로그램)의 상태를 주기적으로 검사하여 일정한 조건을 만족할 때 송수신 등의 자료처리를 하는 방식이라고 하는데 여기서 문제가 나는 것으로 보아 서버 상의 장치 동기화 문제가 아닐까 생각해 본다.