비동기식(Asynchronous) 프로그래밍 구조에서의 디버깅 문제 하나를 이전 글에서 소개했습니다. 오늘은 해당 문제의 원인이 무엇이었고 어떻게 코드를 수정했는지 정리해 보도록 하겠습니다.

→ 비동기식(Asynchronous) 프로그래밍 구조에서 디버깅 문제 (1)

문제 코드

아래는 제가 작성했던 버그 2가지가 있는 모듈의 Pseudoe 코드입니다. 두 코드 조각은 서로 다른 실행 흐름(쓰레드)을 가지고 서로 상호작용합니다. 송신부는 통신 채널로 명령을 전송하고 응답을 대기하고, 수신부는 응답을 수신한 후 송신부에 응답 수신을 알리는 역할을 합니다.

송신부

loop {
	Message command = commandQueue.pop(); // 1

	channel.write(command); // 2

	SyncObject syncObj = new SyncObject(); // 3
	syncMap.put(command.id, syncObj); // 4

	if(!syncObj.wait(2000)) { // 5
		throw new Exception("no response"); // 6
	}
}

수신부

loop {
	Message response= responseQueue.pop(); // 1
	syncObj = syncMap.get(response.id); // 2

	if (syncObj != null) { // 3 
		syncObj.signal();  // 4 
		syncMap.remove(response.id); // 5
	}

	pipeline.next(response); // 6
}

문제 현상

위 코드를 실행하면 간헐적으로 “no response” 예외가 발생합니다. 수신부에서 로그를 남겨보면 응답은 분명하게 수신되고 있습니다. 특이한 점은 수신부 코드에서 수신 이벤트 알람을 주기 위한 동기화 객체가 문제 시점에 null 값이라는 것입니다. 분석해 보니 동기화 객체가 간헐적으로 null 이 되는 이유는 두 가지가 있었습니다.

	if (syncObj != null) { ... } 

예상치 못한 실행 흐름

송신부와 수신부 코드가 실행될 것이라 예상한 흐름은 다음과 같았습니다. 제 머리 속에서는 잘 동작했습니다. 그러나 두 개의 실행 흐름이 어떻게 스위치 되면서 실행되는지 한줄씩 로그를 남기며 확인해 보았더니 전혀 예상치 못한 흐름으로 실행되는 케이스가 발생했습니다.

1. 다음 명령 동기화 객체 삭제
2. 동기화 객체 추가 전 응답 수신

1. 다음 명령 동기화 객체 삭제

문제가 발생하는 시점에는 다음과 같이 절묘한 순서로 코드가 실행되고 있었습니다. 그래서 수신부에서 이전 명령에 대한 동기화 객체 삭제 시 다음 명령어의 동기화 객체를 의도치 않게 삭제하는 문제가 발생했고 실제 다음번 응답이 수신되면 동기화 객체는 null 인 문제가 발생했습니다.

1. 수신부 4번 라인이 실행되며 응답 완료 이벤트가 송신부로 전달된다.
2. 송신부 5번 라인(응답 대기)은 Waiting 상태에서 벗어난다.
3. 수신부 실행은 멈추고, 송신부가 실행을 이어간다. (Context Switch)
4. 송신부는 루프를 돌며 다음 명령어를 큐에서 꺼내고 다음 명령어의 응답 동기화를 위한 객체 생성 및 Map 삽입 까지 완료 한다. (~ 송신부 4번 라인)
5. 다시 수신부가 실행된다. (Context Switch)
6. 수신부 5번 라인에서 Map 에서 동기화 객체를 삭제한다.
7. 이때 다음 명령어 응답 동기화를 위해 삽입한 동기화 객체가 삭제된다. (동일한 메시지 연송 전송되는 상황)

2. 동기화 객체 삽입 전 응답 수신

또한 문제가 발생하는 시점에는 추가적으로 다음과 같은 절묘한 순서로 코드가 실행될 때도 있었습니다. 그래서 송신부에서 명령 전송 후에 동기화 객체 생성하고 Map 에 삽입하기도 전에 응답이 수신되어 수신부에서 동기화 객체가 null 인 문제가 발생하고 있었습니다.

1. 송신부 2번 라인이 실행되며 명령을 채널로 전송한다.
2. 송신부 3번 라인이 실행되며 응답 동기화 객체를 생성한다.
3. 송신부 4번 라인이 실행되기 전에 채널로 부터 응답이 수신되어 수신부 1번 라인이 Waiting 상태에서 깨어난다.
4. 송신부 실행은 멈추고, 수신부가 실행을 이어간다. (Context Switch)
5. 수신부 2번 라인이 실행되면 동기화 객체는 아직 Map 에 삽입되지 않았음으로 null 값이다.

해결하기

크게 코드의 두 부분을 수정함으로 문제를 해결할 수 있었습니다.

1. 응답 동기화 객체는 객체를 생성한 송신부에서 삭제하도록 하여 비동기적으로 발생할 수 있는 타이밍 문제를 제거하였습니다.
2. 명령 전송 전 미리 동기화 객체를 생성하고 Map 에 추가하여 응답이 빨리 수신되더라도 동기화 객체가 null 인 문제를 제거하였습니다.

송신부

loop {
	Message command = commandQueue.pop();

	SyncObject syncObj = new SyncObject(); // 명령 전송 전 동기화 객체 생성과 Map 삽입
	syncMap.put(command.id, syncObj); 

	channel.write(command);

	if(!syncObj.wait(2000)) {
		throw new Exception("no response"); 
	}

	syncMap.remove(response.id); // 동기화 객체 제거
}

수신부

loop {
	Message response= responseQueue.pop(); // 1
	syncObj = syncMap.get(response.id); // 2

	if (syncObj != null) { // 3 
		syncObj.signal();  // 4 
	}

	pipeline.next(response); // 6
}

느낀점

비동기적으로 수행되는 두 개의 실행 흐름에서 발생한 문제는 제 머리속에서 잘 그려지지 않았습니다. 코드를 한 줄 한 줄 디버깅하며 눈으로 보기 전에 전혀 예상이 되지 않았던 것 같습니다. 경험이 많아지면 이런 케이스들이 코드만 보고 눈에 보일까요? 여러분은 어떠셨나요? : ) 글로 옮기다 보니 글로 설명하기도 동기적으로 수행되는 코드를 설명하는 것 보다 훨씬 어려운 것 같습니다.