プログラムの処理時間を計測したい - SAS

SASプログラムの処理時間は、１つのdataステップやプロシージャ単位でログに表示されるのだけど、複数ステップの合計処理時間を取得したい、プログラム全体の処理時間を知りたいとかあるかと思います。処理時間を計測するためには、現在の日時を取得する datetime関数を用いることで計測することができます。

処理時間を計測するテストコード

/* 処理時間を計測したい処理直前の日時をマクロ変数 START_TIME に格納 */
data _null_ ;
  call symputx('START_TIME', datetime()) ;
run ;

/* 処理を計測したいサンプルコード */
data TEST1 ;
  do I=1 to 10000000 ;
    R = ranuni(1) ;
    output ;
  end ;
run ;

/* 処理直後の日時 - 処理直前の日時 = 処理時間 */
data _null_ ;
  PROCESS_TIME = datetime() - &START_TIME. ;
  putlog PROCESS_TIME= ;
run ;

処理時間を計測した実行ログ

 59         data _null_ ;
 60           call symputx('START_TIME', datetime()) ;
 61         run ;
 
 NOTE: DATAステートメント処理(合計処理時間):
       処理時間           0.00 秒
       CPU時間            0.01 秒
       
 
 62         
 63         data TEST1 ;
 64           do I=1 to 10000000 ;
 65             R = ranuni(1) ;
 66             output ;
 67           end ;
 68         run ;
 
 NOTE: データセットWORK.TEST1は10,000,000オブザベーション、2変数です。
 NOTE: DATAステートメント処理(合計処理時間):
       処理時間           1.76 秒
       CPU時間            0.84 秒
       
 
 69         
 70         data _null_ ;
 71           PROCESS_TIME = datetime() - &START_TIME. ;
 72           putlog PROCESS_TIME= ;
 73         run ;
 PROCESS_TIME=1.8770267963
 NOTE: DATAステートメント処理(合計処理時間):
       処理時間           0.12 秒
       CPU時間            0.01 秒

PROCESS_TIME=1.8770267963 という感じでログに処理時間が出力されています。単位は、秒です。

プログラム内で、何度も処理時間を計測したい場合は、上記のコードを何度も書くのは面倒なので、マクロ化してみましょう。処理時間をログに表示させるマクロは、他の方がやられているようなので(本記事下部の参考サイト参照)、実行日時をデータセットに格納して、最後に処理時間をリスト出力するマクロを作ってみます。

処理時間をリスト出力するマクロ

%macro CHECK_PROCESS_TIME(NAME) ;
  /* 現在の実行日時を格納 */
  data PROCESS_TIME_TMP ;
    length NAME $256. ;
    DT = datetime() ;
    NAME = "&NAME." ;
  run ;
  
  /* データセット PROCESS_TIME_SUM がある場合、実行日時を追加 */
  %if %sysfunc(exist(PROCESS_TIME_SUM)) %then %do ;
    proc append base=PROCESS_TIME_SUM data=PROCESS_TIME_TMP ;
    run ;
    proc delete data=PROCESS_TIME_TMP ;
    run ;
  %end ;
  /* データセット PROCESS_TIME_SUM がない場合、データセット名を変更 */
  %else %do ;
    proc datasets lib=WORK nolist ;
      change PROCESS_TIME_TMP = PROCESS_TIME_SUM ;
    quit ;
  %end ;
%mend CHECK_PROCESS_TIME ;


%macro PRINT_PROCESS_TIME() ;
  data PROCESS_TIME_TMP ;
    set PROCESS_TIME_SUM ;
    rename DT = DT_AFTER ;
  run ;
  /* 処理時間を計測する */
  data PROCESS_TIME_PRINT ;
    label NAME         = "処理名"
          PROCESS_TIME = "処理時間"
          DT           = "開始日時"
          DT_AFTER     = "終了日時"
          ;
    format PROCESS_TIME comma10.2
           DT           nldatm30.
           DT_AFTER     nldatm30.
           ;
    set PROCESS_TIME_SUM ;
    set PROCESS_TIME_TMP(firstobs=2) ;
    
    PROCESS_TIME = DT_AFTER - DT ;
  run ;

  proc print data=PROCESS_TIME_PRINT label ;
  run ;
%mend PRINT_PROCESS_TIME ;


/* 以下、サンプルコード --------------------------------------- */

%CHECK_PROCESS_TIME(INIT) ;

data TEST1 ;
  do I=1 to 10000000 ;
    R = ranuni(1) ;
    output ;
  end ;
run ;

%CHECK_PROCESS_TIME(FIRST) ;

data TEST1 ;
  do I=1 to 10000000 ;
    R = ranuni(1) ;
    output ;
  end ;
run ;

%CHECK_PROCESS_TIME(SECOND) ;

/* 処理時間をリスト出力 */
%PRINT_PROCESS_TIME ;

ログに表示させるものだと、処理時間の出力結果が散らばってしまいますが、リスト出力するとぱっと見で処理時間を比較できるのが、メリットかと思います。

---

参考サイト

1. 処理時間計測タイマ
2. SAS：処理時間を計るマクロ | FX and Program Memo