코루틴 Timeout이 제대로 동작하지 않은 이유
개요
코루틴 timeout을 다루며 코루틴 Timeout이 제대로 동작하지 않은 이유에 대해 공유해보고자 합니다.
부제: coroutine timeout dose not work
코루틴의 withTimeout 메서드
public suspend fun <T> withTimeout(timeMillis: Long, block: suspend CoroutineScope.() -> T): T {
contract {
callsInPlace(block, InvocationKind.EXACTLY_ONCE)
}
if (timeMillis <= 0L) throw TimeoutCancellationException("Timed out immediately")
return suspendCoroutineUninterceptedOrReturn { uCont ->
setupTimeout(TimeoutCoroutine(timeMillis, uCont), block)
}
}
withTimeout 메서드를 활용하면 timeMillis 인자로 넘기는 일정 시간이 넘어가는 경우TimeoutCancellationException을 던지게 됩니다.
withTimeout 메서드 호출해 보기
object SuspendMethodClass {
suspend fun printHelloWithSuspend(i: Long) {
var i = 1
logger.info("method is called")
delay(1000L)
logger.info("$i 번째 hello")
}
}
내부적으로 suspend 메서드를 활용하여 1초간 일시중지하고 log를 출력하는 코드를 만들었습니다.
코루틴에서 suspend 메서드를 활용하게 되면 취소에 협조적이게 됩니다.
코루틴 코드가 취소 가능하려면 코루틴이 협력해야 합니다.
kotlinx.coroutines의 모든 일시 중단 함수는 취소할 수 있습니다.
@Test
fun `suspend 메서드로 코루틴 타임아웃 호출해보기`(){
runBlocking {
withTimeout(2000L){
var i= 1L
while(i <= 5){
SuspendMethodClass.printHelloWithSuspend(i++)
}
}
}
}
위의 코드는 2초의 timeout을 주면서 5회 메서드를 호출합니다.
결과는 어떻게 될까요?
2번째의 메서드가 실행되다가 TimeoutCancellationException이 발생하게 됩니다.
타임아웃이 적절하게 발생되는 것 같습니다.
하지만 suspend 메서드가 아니라 동기적으로 실행되는 코드라면 어떨까요?
예를 들어 실제 코드에 HTTP 호출, DB 통신 등 동기적인 상황이라면 어떻게 동작할까요?
동기적인 상황을 만들어 withTimeout 메서드 호출하기
object NotSuspendMethodClass {
fun printHello(i: Long) {
logger.info("method is called")
Thread.sleep(1000)
logger.info("$i 번째 hello")
}
}
이번에는 delay가 아닌 Thead의 sleep 메서드를 활용하도록 구성하였습니다.
해당 메서드는 suspend 메서드가 아니기 때문에 취소에 협조적이지 않습니다.
@Test
fun `suspend 메서드가 아닌 코루틴 타임아웃 호출해보기`(){
runBlocking {
withTimeout(2000L){
var i= 1L
while(i <= 5){
NotSuspendMethodClass.printHello(i++)
}
}
}
}
위의 코드도 2초의 timeout을 주면서 5회 printHello 메서드를 수행시킵니다.
결과는 어떻게 될까요?
예외는 발생하지 않으며 5초가 넘게 메서드가 실행되었습니다.
내부의 코드들도 모두 실행된 모습을 확인할 수 있습니다.
해당 메서드의 Thread.sleep()은 suspend 메서드가 아니며 취소에 협조적이지 않기 때문입니다.
이런 상황에서 설정한 시간(예 2초)에 타임아웃을 발생시키려면 어떻게 해야 할까요?
runInterruptible 활용해 보기
public suspend fun <T> runInterruptible(
context: CoroutineContext = EmptyCoroutineContext,
block: () -> T
): T = withContext(context) {
runInterruptibleInExpectedContext(coroutineContext, block)
}
runInterruptible 메서드는 지정된 코루틴 콘텍스트로 지정된 블록을 인터럽트 가능한 방식으로 호출합니다.
@Test
fun `v2 - suspend 메서드가 아닌 코루틴 타임아웃 호출해보기`(){
runBlocking {
withTimeout(2000L){
runInterruptible {
var i= 1L
while(i <= 5){
NotSuspendMethodClass.printHello(i++)
}
}
}
}
}
2초의 timeout을 주면서 5회 printHello 메서드를 수행시킵니다.
결과는 어떻게 될까요?
이번에는 의도한 대로 2초의 타임아웃이 동작하였고 2번째 메서드까지만 호출되었습니다.
하지만 runInterruptible의 경우 내부에서 Thread.interrupted()를 활용하기 때문에 Thread.sleep()으로 블로킹된 것이 아니라면 잘 동작하지 않을 수 있습니다.
만약 HTTP를 내부에서 호출하는 경우도 잘 동작할까요?
runInterruptible으로 http 메서드 호출해 보기
fun httpRequest(i: Long){
logger.info("method is called")
var restTemplate = RestTemplate()
restTemplate.getForEntity<String>("http://localhost:8080/test")
logger.info("$i 번째 httpRequest")
}test라는 존재하지 않는 경로의 조회를 요청해 보도록 하겠습니다.
@Test
fun `v3 - 코루틴 타임아웃에 http 메서드 호출해보기`(){
runBlocking {
withTimeout(500){
runInterruptible {
var i= 1L
while(i <= 5){
runCatching {
NotSuspendMethodClass.httpRequest(i)
}
i++
}
}
}
}
}500ms의 timeout을 두고 http 메서드를 호출해 보았습니다.
결과는 어떻게 될까요?
예외 메시지는 타임아웃이 발생한 것처럼 보이지만 실제 동작시간을 살펴보면 928ms가 소요되었습니다.
또한 5번의 메서드가 모두 호출된 모습을 확인할 수 있습니다.
만약 runCatching 코드로 예외를 잡지 않으면 API가 존재하지 않기 때문에 ResourceAccessException이 발생하게 됩니다.
이런 HTTP의 경우에도 타임아웃이 적시에 발생하게 하려면 어떻게 해야 할까요?
또 다른 코루틴을 만들어 비동기로 호출하기
동기적인 작업의 경우에도 타임아웃이 적시에 발생하게 하기 위해서는 또 다른 코루틴을 하나 만들고 해당 작업을 위임해야 합니다.
fun httpRequest(i: Long){
logger.info("method is called")
Thread.sleep(1000L)
var restTemplate = RestTemplate()
restTemplate.getForEntity<String>("http://localhost:8080/test")
logger.info("$i 번째 httpRequest")
}
조금 더 가시적인 테스트를 위해 httpRequest 메서드에 Thread.sleep()으로 1초의 대기시간을 주었습니다.
@Test
fun `v4 - 또 다른 코루틴을 활용해야 한다`(){
val startTime = System.currentTimeMillis()
logger.info { "현재 쓰레드는 무엇일까 : ${Thread.currentThread().name}" }
runBlocking {
logger.info { "현재 쓰레드는 무엇일까 : ${Thread.currentThread().name}" }
try {
withTimeout(1000) {
logger.info { "현재 쓰레드는 무엇일까 : ${Thread.currentThread().name}" }
CoroutineScope(Dispatchers.IO).async {
logger.info { "현재 쓰레드는 무엇일까 : ${Thread.currentThread().name}" }
var i = 1L
while (i <= 5) {
runCatching {
NotSuspendMethodClass.httpRequest(i)
}
i++
}
}.await()
}
} catch (e: TimeoutCancellationException){
val endTime = System.currentTimeMillis()
println("Timeout이 발생하는 시점은 시스템이 시작되고 ${endTime-startTime} 이후 이다.")
}
}
Thread.sleep(5000L)
}
1초의 timeout을 두고 5번의 http 호출과 Thread.sleep(1000) 작업을 호출합니다.
아마 내부적인 작업은 5번 호출되니 최소 5초 이상이 소요될 것입니다.
비동기의 내부적인 작업이 모두 호출되는 것을 확인하기 위해서 마지막에는 Thread.sleep(5000)로 5초의 대기를 주었습니다.
그리고 마지막에 Thread.sleep(5000)을 주기 때문에 타임아웃이 발생한 시점을 계산하기 위해 TimeoutCancellationException을 잡아서 타임아웃에 걸린 시간을 출력합니다.
여기에서 핵심은 새로운 쓰레드(Dispatchers.IO)가 할당된 CoroutineScope를 만들어서 비동기로 작업을 위임하는 것입니다.
결과는 어떻게 될까요?
처음에는 Test worker 스레드가 출력되다가 새로운 CoroutineScope에서 호출되었을 때는 DefaultDispacher-worker 스레드가 호출됩니다.
이후 타임아웃은 1175ms에 발생하였습니다.
이후에 비동기 작업에 남아있던 4번의 메서드가 1초 간격으로 호출됩니다.
그런데 비동기로 작업만 위임하면 될 것 같은데 왜 CoroutineScope 만들고 쓰레드를 할당할까요?
CoroutineScope에 새로운 쓰레드를 할당하는 이유
as-is
CoroutineScope(Dispatchers.IO).async {...}
to-be
async {...}
기존예제의 방식이 아닌 단순하게 async로 바꾸어 보겠습니다.
결과는 어떻게 될까요?
이제 모든 쓰레드는 Test worker가 담당하게 되고, 5번의 메서드가 모두 호출되고 나서야 5986ms 이후에 타임아웃 예외가 발생합니다.
즉, 타임아웃이 의도된 시간에 발생하지 않게 됩니다.
쓰레드의 하나의 차이가 왜 이런 결과를 만들어낼까요?
기존에는 비동기 작업을 새로운 쓰레드에서 수행하기 때문에 기존의 Test worker 쓰레드는 타임아웃이 발생했는지 주기적으로 검사할 수 있습니다.
그런데 코루틴은 경량쓰레드 아닌가요?
Test worker 스레드에서도 서로 다른 @coroutine#1 @coroutine#2를 사용하는 것 같은데 왜 타임아웃을 검사할 수 없을까요?
서로 다른 코루틴의 작업이 취소에 협력적이라면 즉 suspend 메서드를 사용한다면 타임아웃을 검사할 수 있을 것입니다.
하지만 @coroutine#2 에서 일어나는 작업은 Blocking I/O 작업으로 타임아웃에 영향을 줄 수 없기 때문에 쓰레드의 격리를 수행해야 합니다.
이런 방식과 유사하게 Netflix의 Hystrix는 쓰레드 격리 전략을 기본적으로 수행합니다.
이를 통하여 네트워크상의 타임아웃 위에 스레드 타임아웃 전략을 가져갈 수 있습니다.
asyncAwaitWithTimeout 메서드 만들기
fun<T> asyncAwaitWithTimeout(timeMillis: Long, block: suspend CoroutineScope.() -> T): T{
return runBlocking {
withTimeout(timeMillis) {
CoroutineScope(Dispatchers.IO).async {
block()
}.await()
}
}
}타임아웃 내에 실행할 로직들을 block 인자로 넘겨서 실행하는 asyncAwaitWithTimeout 메서드입니다.
depth도 깊어지고 CoroutineScope를 생성하지 않거나 쓰레드를 할당하지 않는 실수를 할 수 있기 때문에 asyncAwaitWithTimeout 메서드를 만들어서 Blocking I/O 작업에 타임아웃이 필요한 경우 활용해 볼 수 있습니다.
주의할 점
동기적인 작업의 타임아웃을 적시에 가져갈 수 있다는 장점이 있지만 2가지 주의해야 할 점이 있습니다.
위의 구조는 Coroutine의 구조화된 동시성(Structured Concurrencey)을 활용할 수 없습니다.
구조화된 동시성을 활용하지 못한다는 것은 withTimeout이 발생했을 때 자식 코루틴이 자동적으로 취소되지 않는다는 것을 뜻합니다.
CoroutineScope에 새로운 쓰레드를 할당하고 비동기로 호출하기 때문에 타임아웃을 검사하는 쓰레드의 코루틴과 자식관계가 아니게 됩니다.
예시코드) 타임아웃이 발생한 후 5초 Sleep
@Test
fun `asyncAwaitWithTimeout 메서드를 만들어서 템플릿화`(){
val startTime = System.currentTimeMillis()
try {
val result = asyncAwaitWithTimeout(1000L) {
var i = 1L
while (i <= 5) {
SuspendMethodClass.printHelloWithSuspend(i++)
}
}
println(result)
} catch (e: Exception){
val endTime = System.currentTimeMillis()
println("Timeout이 발생하는 시점은 시스템이 시작되고 ${endTime-startTime} 이후 이다.")
}
sleep(5000L)
}asyncAwaitWithTimeout 메서드를 활용하여 1초의 시간이 경과하면 타임아웃을 발생하도록 구성하였습니다.
또한 내부로직은 취소에 협력할 수 있는 suspend 메서드로 구성되어 있습니다.
이후에는 백그라운드에서 비동기 작업이 실행되는지 확인하기 위해 타임아웃이 발생하고 sleep(5000L)을 통해 5초 동안 기다렸다가 테스트를 끝내보겠습니다.
테스트 결과)
1초 뒤에 타임아웃이 발생하였지만 이후에 4번의 메서드가 호출되었음을 확인할 수 있습니다.
만약 새로운 쓰레드를 할당해서 코루틴을 생성하지 않았다면 구조화된 동시성의 이점을 활용하여 타임아웃 이후 메서드들이 호출되지 않을 것입니다.
마무리
이전에 경험해보지 못한 기술을 적용해야 하는 시점에는 기술을 잘 이해하지 못하여 예상하지 못한 결과가 발생할 수 있습니다.
이를 방지하긴 위해서는 다양한 학습 테스트를 해보고 동작에 대해 이해해 보는 시간을 가져보는 것이 좋은 것 같습니다.
이번 기회를 통하여 코루틴과 조금은 친해진 것 같습니다.
참고자료
https://kotlinlang.org/docs/cancellation-and-timeouts.html
https://techblog.woowahan.com/2542/
https://github.com/Netflix/Hystrix/wiki/How-it-Works#isolation