- 서론
다수의 서버를 사용하는 실시간 분산 시스템(Apache Kafka, Apache Storm 등)에서 시간 성능을 측정할 일이 생겼다.
성능 측정을 위해 A서버가 B서버에게 메시지를 전송할 때, A서버에서 송신시간을 측정하고 B서버에서 수신시간을 측정하여 {수신시간 - 송신시간}으로 전송시간을 계산하려고 하였다.
이때, 실시간 시스템이 워낙 빠르게 데이터를 주고 받으니 Java의 System.nanoTime()으로 송신시간과 수신시간을 측정했다.
그런데 측정된 시간으로 전송시간({수신시간 - 송신시간})을 계산해보니 음수가 나오는 문제가 발생했다.
즉, 이는 송신시간이 수신시간보다 더 느리다는 뜻이다.
어디서 이런 문제가 발생했을까?
- 본론
혹시 다른 프로세스에서 System.nanoTime()을 출력하면 다른 값이 나오는걸까?
먼저 아래와 같이 10ms(0.01초)마다 System.nanoTime()을 출력하는 간단한 프로그램을 작성해보았다.
1 2 3 4 5 6 7 8 9 10 | public class App { public static void main( String[] args ) throws InterruptedException { while (true) { System.out.println( args[0] + ": " + System.nanoTime() ); Thread.sleep(10); } } } | cs |
이 프로그램을 두 개의 프로세스로 동작시켰더니 아래와 같은 결과가 나왔다.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 | [admin@vm~]$ java -cp test-nanosecond.jar App test01 & java -cp test-nanosecond.jar App test02 & [1] 3384 [2] 3385 test01: 9990558350836 test02: 9990562699619 test01: 9990568550330 test02: 9990572910761 test01: 9990578835578 test02: 9990583035689 test01: 9990588908712 test02: 9990593405835 test01: 9990599289354 test02: 9990604186813 test01: 9990610090038 test02: 9990614317801 test01: 9990621349641 test02: 9990624723916 test01: 9990631595658 test02: 9990635501565 test01: 9990641702175 test02: 9990645620668 test01: 9990652082446 test02: 9990655972680 test01: 9990662856546 test02: 9990666745119 test01: 9990672977516 test02: 9990676842676 (이하 생략) | cs |
실험 결과, test01 프로세스와 test02 프로세스가 출력하는 System.nanoTime()은 서로 반복적으로 교차하지만 선형적으로 증가함을 확인하였다.
즉, 서버 내에서 동작하는 서로 다른 프로세스에서는 System.nanoTime()이 꼬이지 않고 정상적으로 측정된다.
이제 두 개의 서버에서 위의 프로세스를 하나씩 동작시켜보자.
실험은 MobaXterm의 Multi-execution mode를 사용하여 동시에 실행하였다.
실험 결과는 아래와 같다.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 | [admin@vm1 ~]$ java -cp test-nanosecond.jar App test01 test01: 10471422550227 test01: 10471433277287 test01: 10471443430335 test01: 10471453691607 test01: 10471463805147 test01: 10471474252026 test01: 10471484969633 test01: 10471495117322 test01: 10471505516197 test01: 10471516402940 test01: 10471527116008 test01: 10471537546092 test01: 10471547990703 | cs |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 | [admin@vm2 ~]$ java -cp test-nanosecond.jar App test02 test02: 10467594802870 test02: 10467605744154 test02: 10467616455625 test02: 10467627232689 test02: 10467637970750 test02: 10467648788369 test02: 10467659470987 test02: 10467670270827 test02: 10467681010944 test02: 10467691769703 test02: 10467702478691 test02: 10467713257345 test02: 10467724012165 | cs |
실험 결과를 보면, 쉘의 입출력 시간과 터미널이 결과를 보여주는 시간을 고려하더라도 큰 차이가 있음을 알 수 있다.
예를 들어, 각 2번 라인을 보면 test01이 test02에 비해 3,827,747,357이 더 크다.
System.nanoTime()은 나노 초(10^-9 초)를 측정하므로, test01이 test02에 비해 약 3.8초 정도 느린 시간을 측정한다는 것이다.
이로써 System.nanoTime()을 서버 간의 시간 성능 측정에 사용할 경우 수 초 정도의 오차가 발생함을 확인하였다.
이러한 문제의 원인은 System 클래스의 Java doc을 통해 확인할 수 있었다.
Java doc의 nanoTime() 메서드 설명을 보면 아래의 설명이 있었다.
Returns the current value of the running Java Virtual Machine's high-resolution time source, in nanoseconds.
(중략)
The same origin is used by all invocations of this method in an instance of a Java virtual machine; other virtual machine instances are likely to use a different origin.
즉, System.nanoTime() 메서드는 JVM을 기준으로 나노초를 측정하며, 다른 JVM에서는 기준이 다르다는 뜻이다.
이러한 이유로 서로 다른 서버에서 측정한 나노초는 오차가 발생하는 것이다.
- 결론
Java의 System.nanoTime()은 같은 서버에서 서로 다른 프로세스로 동작시킬 경우에는 결과가 꼬이는 문제가 발생하지 않는다.
하지만 서로 다른 서버에서 시간 성능 측정으로 사용할 경우에는 수 초 정도의 오차가 발생할 수 있다.
따라서 서로 다른 서버에서는 단위가 조금 크더라도 System.currentTimeMillis()를 사용해야 한다.
System.currentTimeMillis() 함수는 운영체제로부터 시간을 가져오므로 서버들의 시간 동기화를 잘 맞춰준다면 초 단위의 오차를 없앨 수 있다.
(시간 동기화 후에 추가로 실험해보니 System.currentTimeMillis()은 초 단위의 오차가 발생하지 않았다.)
- 실험 환경
OS: CentOS 7
JVM: 1.8