date +"%Y-%m-%d %H:%M:%S.%N"
1 2 | [user@vm ~]$ date +"%Y-%m-%d %H:%M:%S.%N" 2017-10-17 20:47:09.783257914 | cs |
%Y: 연
%m: 월
%d: 일
%H: 시
%M: 분
%S: 초
%N: 나노초
Linux command to get time in milliseconds, https://stackoverflow.com/questions/16548528/linux-command-to-get-time-in-milliseconds
How To Format Date For Display or Use In a Shell Script, https://www.cyberciti.biz/faq/linux-unix-formatting-dates-for-display/
| gawk로 csv format 텍스트를 split 하기 (0) | 2018.07.15 |
|---|
다수의 서버를 사용하는 실시간 분산 시스템(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