TIC, TOC 명령을 활용한 시간 측정 방법

오늘은 IDL에서 특정한 프로세스가 돌아가는데 걸리는 시간을 측정할 때 사용하는 TIC, TOC 명령들에 관하여 간략히 살펴볼까 합니다. 사실 TIC, TOC 명령들은 제가 이 블로그에서 올린 몇몇 게시물들에서도 이미 여러번 사용한 바 있습니다. 사용 방법은 매우 간단하며 마치 스톱워치처럼 사용하면 됩니다. 즉 TIC 명령을 실행하면 시간 측정이 시작되고 TOC 명령을 실행하면 시간 측정이 멈추면서 그때까지 경과한 시간을 초 단위로 표시해줍니다. 먼저 다음과 같이 IDL의 명령 프롬프트에서 간단히 시도해봅시다.

 

IDL> TIC
IDL> TOC
% Time elapsed: 3.4210000 seconds.

 

이와 같이 TIC 명령을 실행하고 어느 정도 이후에 TOC 명령을 실행하면 경과 시간 즉 TIC 명령이 실행된 순간부터 TOC 명령이 실행된 순간까지 경과된 시간을 초 단위로 측정하여 출력해줍니다. 명령 프롬프트 뿐 아니라 프로그램 내에서도 특정한 프로세스가 실행되는데 소요되는 시간을 측정할 목적으로 사용할 수 있습니다. 이러한 예제를 보면 다음과 같습니다.

 

a = FINDGEN(10001)
n = N_ELEMENTS(a)

TIC
FOR j = 0, n-1 DO PRINT, j, a[j], SQRT(a[j])
TOC

 

여기서는 반복형 구문이 끝까지 실행되기까지 총 어느 정도의 시간이 걸리는가를 정량적으로 확인하기 위하여 TIC, TOC 명령을 사용하였습니다. 위의 내용을 실행하면 총 10001회에 걸친 반복 작업에 의하여 매 회차마다 출력이 진행되고, 반복 작업이 모두 종료된 이후에는 측정 시간이 표시될 것입니다. 출력 내용의 맨 뒷부분만 보면 다음과 같습니다.

 

    9997      9997.00      99.9850
    9998      9998.00      99.9900
    9999      9999.00      99.9950
   10000      10000.0      100.000
% Time elapsed: 1.6440001 seconds.

 

여기서는 1.644초가 걸린 것으로 확인됩니다. 물론 이러한 수치는 프로그램을 실행할 때마다 조금씩 달라질 수 있으며, 여러분의 PC에서는 아마 다르게 측정될 것입니다. 어쨌든 이와 같은 특성 때문에 IDL 프로그램을 작성하면서 특정한 프로세스에 대하여 구동 시간을 측정할 목적으로 유용하게 사용될 수 있습니다. 그러면 TIC, TOC 명령의 사용법에 관하여 한 단계 더 들어가보겠습니다. 이번 예제는 다음과 같습니다.

 

ni = 1000000
nj = 10
a = FINDGEN(ni, nj)
r = FLTARR(ni, nj)
TIC
FOR j = 0, nj-1 DO BEGIN
  FOR i = 0, ni-1 DO BEGIN
    r[i, j] = a[i, j]^0.6+a[i, j]^0.3
  ENDFOR
ENDFOR
TOC

 

이번 예제는 이중 루프의 형태를 띄는 작업입니다. 여기서 ni는 1000000이고 nj는 10이므로 전체적인 반복 횟수는 1000000x10 즉 10000000회(천만 회)가 됩니다. 세부적으로는 안쪽 루프인 i 루프가 1000000회 반복 그리고 바깥쪽 루프인 j 루프가 10회 반복을 하게 됩니다. 그리고 이중 루프 작업의 전체적인 소요 시간을 측정하기 위하여 TIC, TOC 명령을 사용하였습니다. 이렇게 실행을 하면 측정된 시간이 출력됩니다. 제 컴퓨터에서는 다음과 같이 약 1.5초 정도가 걸리는 것으로 출력되었습니다.

 

% Time elapsed: 1.4879999 seconds.

 

그런데 이중 루프의 전체적인 작업 시간 뿐 아니라 안쪽 루프에 대한 작업 시간도 매회 측정하고 싶은 경우를 가정해봅시다. 즉 안쪽 루프인 i 루프는 1000000회의 반복 작업을 하는데 그 소요 시간을 측정하는 것입니다. 그러면 총 10회에 걸쳐 안쪽 루프의 소요 시간을 측정하게 됩니다. 이를 위해서는 다음과 같이 TIC, TOC 명령을 j 루프 안쪽에서 추가로 사용해주면 될 것으로 보입니다.

 

ni = 1000000
nj = 10
a = FINDGEN(ni, nj)
r = FLTARR(ni, nj)
TIC
FOR j = 0, nj-1 DO BEGIN

  TIC
  FOR i = 0, ni-1 DO BEGIN
    r[i, j] = a[i, j]^0.6+a[i, j]^0.3
  ENDFOR

  TOC
ENDFOR
TOC

 

이와 같이 안쪽 루프에 대해서도 시간 측정을 할 수 있도록 TIC, TOC 명령들을 추가한 다음 다시 실행을 해봅시다. 제가 이 내용을 실행하여 얻은 출력 내용을 보면 다음과 같았습니다.

 

% Time elapsed: 0.14400005 seconds.
% Time elapsed: 0.14499998 seconds.
% Time elapsed: 0.14100003 seconds.
% Time elapsed: 0.15599990 seconds.
% Time elapsed: 0.15000010 seconds.
% Time elapsed: 0.14499998 seconds.
% Time elapsed: 0.14599991 seconds.
% Time elapsed: 0.15000010 seconds.
% Time elapsed: 0.14400005 seconds.
% Time elapsed: 0.14599991 seconds.
% Time elapsed: 0.14599991 seconds.

 

일단 이 내용을 보면 10회에 걸쳐 바깥쪽 루프가 돌 때마다 안쪽 루프의 소요 시간이 측정되어 출력된 것을 확인할 수 있습니다. 매 회당 약 0.14~0.15초인데, 앞서 전체 작업의 소요 시간이 약 1.4~1.5초였던 것을 감안하면 맞는 수치인 것으로 보입니다. 그런데 출력 내용의 마지막 두 줄을 보면 그 수치가 서로 완전히 동일합니다. 원래 맨 마지막 출력 내용은 이중 루프의 전체 소요 시간이 되도록 하였는데, 그 의도와는 전혀 다른 결과입니다. 이것은 여기서 사용된 TIC, TOC 명령들의 시작과 끝이 서로 뒤섞이면서 발생한 문제입니다. 즉 TOC 명령이 측정하는 시간은 무조건 바로 이전 가장 최근에 TIC 명령이 실행된 시점을 기준으로 한다는 특성 때문입니다. 따라서 여기서 맨 마지막에 사용된 TOC 명령은 원래 의도는 맨 처음(이중 루프 작업의 시작 직전)에 명시된 TIC 명령을 시점으로 인식하도록 한 것이었으나, 실제로는 안쪽 루프의 맨 마지막 10회차에서 사용된 TIC 명령이 그 시점으로 간주되는 바람에 이와 같이 우리의 의도와는 다른 측정 결과를 산출한 것입니다.

 

따라서 TIC, TOC 명령이 서로 올바르게 짝지어지도록 하여 이러한 혼란을 방지할 수 있는 방법이 있다면 좋을 것 같은데, 다행히도 그러한 방법은 있습니다. 바로 TIC, TOC 명령의 쌍이 서로 구분되도록 고유의 ID를 부여하는 기능을 활용하면 됩니다. 이러한 기능을 활용하여 위의 내용을 수정해보면 다음과 같습니다.

 

ni = 1000000
nj = 10
a = FINDGEN(ni, nj)
r = FLTARR(ni, nj)
clk_total = TIC('for the entire process')
FOR j = 0, nj-1 DO BEGIN
  TIC
  FOR i = 0, ni-1 DO BEGIN
    r[i, j] = a[i, j]^0.6+a[i, j]^0.3
  ENDFOR
  TOC
ENDFOR
TOC, clk_total

 

여기서는 이중 루프의 전체 소요 시간을 측정하는데 있어서 TIC, TOC 명령이 사용된 새로운 방식에 주목해야 합니다. 특히 여기서는 TIC 명령을 함수의 형태로 사용하였습니다. 먼저 TIC 함수 내에 명시된 'for the entire process'는 유저가 지정한 문자열이며 나중에 TOC 명령이 시간을 출력할 때 함께 표시되도록 할 목적으로 부가적으로 사용한 것입니다. 그리고 TIC 함수의 좌변에 있는 clk_total이 바로 고유 ID의 역할을 합니다. 그래서 맨 마지막에서 사용된 TOC 명령에서 바로 이 clk_total이 인수로 사용된 것을 함께 주목하면 됩니다. 즉 TIC 함수를 사용하면서 고유 ID를 정의하고 TOC 명령에서 이를 인수로 활용하도록 하면 됩니다. 이렇게 하면 이 TOC 명령은 시간 측정의 시점을 clk_total에 해당되는 TIC 명령이 실행된 시점으로 정확히 인식하게 됩니다. 이와 같은 수정 사항을 반영하여 다시 실행해보면 출력 결과는 다음과 같습니다.

 

% Time elapsed: 0.14499998 seconds.
% Time elapsed: 0.14299989 seconds.
% Time elapsed: 0.14000010 seconds.
% Time elapsed: 0.14199996 seconds.
% Time elapsed: 0.14600015 seconds.
% Time elapsed: 0.14299989 seconds.
% Time elapsed: 0.14199996 seconds.
% Time elapsed: 0.14300013 seconds.
% Time elapsed: 0.14599991 seconds.
% Time elapsed: 0.14599991 seconds.
% Time elapsed for the entire process: 1.4359999 seconds.

 

이 내용을 보면 안쪽 루프들에 대한 소요 시간 및 전체 작업의 소요 시간이 명확히 구분되어 측정된 것을 확인할 수 있습니다. 따라서 프로그램 내에서 다수의 부분 프로세스들에 대하여 시간 측정을 해야 할 경우에는 이와 같이 각각의 TIC, TOC 명령의 쌍들에 대하여 고유 ID를 부여하여 활용하면 시간 측정 결과의 혼란을 막을 수 있습니다. 그리고 이왕이면 안쪽 루프 작업들에 대한 시간 측정에 대해서도 비슷한 방식으로 고유 ID를 부여하여 구분해주는 것이 더 바람직할 것 같습니다.

 

ni = 1000000
nj = 10
a = FINDGEN(ni, nj)
r = FLTARR(ni, nj)
clk_total = TIC('for the entire process')
FOR j = 0, nj-1 DO BEGIN
  clk_inside = TIC('for inner loop '+STRTRIM(STRING(j), 2))
  FOR i = 0, ni-1 DO BEGIN
    r[i, j] = a[i, j]^0.6+a[i, j]^0.3
  ENDFOR
  TOC, clk_inside
ENDFOR
TOC, clk_total

 

이와 같이 안쪽 루프들에 대해서도 비슷한 처리를 해주면 출력 결과는 다음과 같습니다.

 

% Time elapsed for inner loop 0: 0.14599991 seconds.
% Time elapsed for inner loop 1: 0.13900018 seconds.
% Time elapsed for inner loop 2: 0.14399981 seconds.
% Time elapsed for inner loop 3: 0.14400005 seconds.
% Time elapsed for inner loop 4: 0.15000010 seconds.
% Time elapsed for inner loop 5: 0.14599991 seconds.
% Time elapsed for inner loop 6: 0.14400005 seconds.
% Time elapsed for inner loop 7: 0.14499998 seconds.
% Time elapsed for inner loop 8: 0.14100003 seconds.
% Time elapsed for inner loop 9: 0.14499998 seconds.
% Time elapsed for the entire process: 1.4449999 seconds.

 

출력 내용을 보면 측정된 시간들이 각각 어떤 프로세스에 대한 것인가를 명확하게 구분하여 확인할 수 있습니다. 따라서 TIC, TOC 명령은 단순하게 사용할 수도 있지만, 방금 소개한 것처럼 고유의 ID를 부여하면 다수의 TIC, TOC 쌍들이 사용될 때 서로를 구분할 수 있으므로 좀 더 다양한 방식의 활용이 가능하다는 점을 참조해두시면 좋을 것 같습니다.

 

 

 

* 이 글이 도움이 되었다면 게시물에 대하여 공감 버튼(하트 모양) 클릭 및 블로그 구독도 해주시면 더 큰 힘이 됩니다. 감사합니다.