[Kotlin Coroutines] Log 를 사용한 Coroutines 디버깅

로그를 사용한 디버깅의 필요성

Kotlin Coroutines는 같은 Coroutine Builder(launch, async 등) 의 중괄호 내부의 코드들이 다른 스레드에서 실행될 수 있다. 예를 들어 아래 코드에서 "task1 : start" 는 메인 스레드에서 실행되지만, "task1 : end"는 DefaultExecutor 스레드에서 실행된다.

 

import kotlinx.coroutines.*

fun main() = runBlocking<Unit> {
    val task1 = launch(Dispatchers.Unconfined) {
        log("task1 : start")
        delay(100)
        log("task1 : end")
    }
    val task2 = launch {
        log("task2 : start")
        delay(100)
        log("task2 : end")
    }

    listOf(task1,task2).joinAll()
}

fun log(message: String) = println("[Current Thread : ${Thread.currentThread().name}] $message")

 

출력은 다음과 같다.

[Current Thread : main] task1 : start
[Current Thread : main] task2 : start
[Current Thread : kotlinx.coroutines.DefaultExecutor] task1 : end
[Current Thread : main] task2 : end

 

위의 출력만 가지고 "task1 : start" 와 "task1 : end"가 같은 코루틴에서 실행된다는 것을 알 수 있을까? 당연히 그렇지 않다. 일반적인 프로그래밍에서는 같은 블록 내부의 작업에서 실행 스레드가 바뀌지 않기 때문이다.

 

따라서 Thread.currentThread().name을 사용하여 현재 스레드를 출력하는 것만으로는 위에서 Coroutine에 대한 정보를 모두 나타내지 못한다. JVM에서는 위 로깅을 위한 코드를 전혀 바꾸지 않고 코루틴에 대한 정보를 출력하기 위한 옵션을 제공한다.

 

로그를 사용해 코루틴 디버깅 하기

로깅을 통해 Coroutines 디버깅하기 위해서는 JVM을 위해 특정 옵션이 추가되어야 한다. 이를 추가하기 위해 아래 과정을 따라하자.

 

1. fun main() 왼쪽의 재생 버튼을 누른 후 [Modify Run Configuration...] 을 클릭한다. 

 

2. -Dkotlinx.coroutines.debug 를 VM options에 넣은 후 OK 버튼을 클릭한다.

 

3. 위 코드를 다시 실행해 보자. 이제 실행 스레드의 @ 뒤에 어떤 코루틴에서 작업이 수행되었는지가 출력된다.

[Current Thread : main @coroutine#2] task1 : start
[Current Thread : main @coroutine#3] task2 : start
[Current Thread : kotlinx.coroutines.DefaultExecutor @coroutine#2] task1 : end
[Current Thread : main @coroutine#3] task2 : end

 

정리

위 과정을 통해 로깅을 통해 Coroutines의 디버깅이 가능해진 것을 확인할 수 있다. 많은 로깅 프레임워크들에서는 Thread.currentThread().name 을 사용해 Thread를 로깅한다. 따라서 VM options에 -Dkotlinx.coroutines.debug만 추가해서 실행하면 어떤 코루틴에서 실행되는지를 확인할 수 있게 된다.