実行時間の測定 DouKaku?

実行時間の測定

ある比較的重たい処理をする関数「func」があるとします。この関数を呼び出して、その実行にかかった時間を表示する関数「profile」を書いてください。

言語として可能であれば、「profile」が「func」と同じ引数で呼び出せるようにしてください。

Posted feedbacks - Nested

Flatten Hidden

「同じ引数で…」ということは、funcは決め打ちでいいのかな。

1	(define (profile . args) (time (apply func args)))

Common Lisp には TIME マクロが標準機能として規格に入ってます

CL-USER> (defun func (n) (if (<= n 0) 'ok (foo (1- n))))
FOO
CL-USER> (compile 'func)
FOO
NIL
NIL
CL-USER> (time (func 100000))
; cpu time (non-gc) 15 msec user, 0 msec system
; cpu time (gc)     0 msec user, 0 msec system
; cpu time (total)  15 msec user, 0 msec system
; real time  5 msec
; space allocation:
;  1 cons cell, -32 other bytes, 0 static bytes
OK

関数にしないとだめかな…

1	(defun profile (&rest args) (time (apply #'func args)))

何のひねりもなしでつ＞＜

var profile = function() {
  var start = new Date;
  func.apply(this, arguments);
  alert((new Date).getTime() - start.getTime() + 'ms');
};

安直

def profile (*args, &block)
	before = Time.now
	func(*args, &block)
	puts "profile: #{Time.now - before} sec"
end

かぶってそう…

require 'benchmark'
def profile(&block)
  real = Benchmark::measure(&block).real
  $stderr.puts "#{real} secs"
end

def func
  puts "output from func"
  sleep 1
end

profile { func }

luaは整数秒しか出なくて困る＞＜高階関数が使えるから、これでいいよね。

function profile(block)
  start = os.clock()
  block()
  endt = os.clock()
  print(string.format("%s secs", os.difftime(endt, start)))
end

function func(n)
  print("output from func")
  for i = 1, n, 1 do
    -- do nothing
  end
end

profile( function() func(100000000) end )

主要な環境では os.clock の精度は秒より細かいはずで、単に引き算すればよいと思います。また os.difftime が引数として期待する時刻は os.time が返すような値（普通エポックからの秒数）なので os.clock の戻り値（システム依存の精度の CPU 時間）を与えるのは適切でないと思います。整数秒しか出ないのは多分 os.difftime のせいで、それでもうまく行っているように見えるのは os.difftime を突き詰めていくと結局引き算（おそらく整数の）にたどり着くからだと思われます。

ほんとですね。
> === os.difftime (t2, t1)
> 時刻 t1 から時刻 t2 までの秒数を返す。 POSIX や Windows、その他のいくつかのシス
> テムでは、この値は t2-t1 に等しい。
マニュアルの説明からでは思い付きませんでした。ありがとうございます。

elispだとビット数の制限のせいでcurrent-timeの表現が複雑…

(require 'cl)
(defun profile (block)
  (labels ((timediff (s e)
             (destructuring-bind (h1 l1 m1) s
               (destructuring-bind (h2 l2 m2) e
                 (+ (* 65536 (- h2 h1)) (- l2 l1) (* 0.000001 (- m2 m1)))))))
    (let ((s-time (current-time)) e-time)
      (funcall block)
      (setq e-time (current-time))
      (message "%s secs" (timediff s-time e-time)))))

;; (profile (lambda () (sit-for 1)))

erl -noshell -eval 'profile:profile([1, 2]),init:stop().'
のように実行します．

任意の可変長の引数をとる方法はないはずなので，引数のリストを渡すか，
必要と予想される引数の個数まで定義をたくさん書くしか方法はないと思います．

今回は引数のリストを渡す形にしました．

-module(profile).
-export([profile/1, func/2]).

func(A, B) ->
    io:format("func ~w ~w~n", [A, B]).

profile(Args) ->
    io:format("~w~n", [timer:tc(?MODULE, func, Args)]).

using System;
using System.Diagnostics;
using System.Threading;
class Program
{
  public delegate void Func(params object[] args);
  static void Main()
  {
    Func de1 = delegate(object[] args) { func((string)args[0]); };
    profile(de1, "test1");
    Func de2 = delegate(object[] args) { func2((int)args[0], (string)args[1]); };
    profile(de2, 123, "test2");
  }
  static void profile(Func de, params object[] args)
  {
    Stopwatch sw = new Stopwatch();
    sw.Start();
    de(args);
    sw.Stop();
    Console.WriteLine("{0} sec", sw.Elapsed.TotalSeconds);
  }
  static void func(string s)
  {
    Console.WriteLine("Start func {0}", s);
    Thread.Sleep(1000);
  }
  static void func2(int i, string s)
  {
    Console.WriteLine("Start func2 {0} {1}", s, i);
    Thread.Sleep(1000);
  }
}

Rでは可変引数は扱えないようなので、引数のリストを渡すか、決めうちか、
func(a,b,c)ごと渡すしかないようです。

> profile(100,10,1)
user : 76.56
sys : 0.110000000000000
total : 82.0100000000001
cumulative user : NA
cumulative sys : NA

profile <- function(a, b, c){
    cat(paste(c("user", "sys", "total", "cumulative user", "cumulative sys"), 
        system.time(func(a,b,c)), sep=" : "), sep="\n")
}

func <- function(a,b,c){
    for (i in 1:1000000) sample(a:b)
    for (i in 1:1000000) sample(a:c)
    for (i in 1:1000000) sample(b:c)
}

すいませんウソつきました。"..."で可変長引数を扱えるようです。

profile <- function(...){
    cat(paste(c("user", "sys", "total", "cumulative user", "cumulative sys"), 
        system.time(func(...)), sep=" : "), sep="\n")
}

これでいけるんだっけかな。

import time

def profile(f, *a, **b):
  t = time.time()
  f(*a, **b)
  return time.time() - t

def func(a, b, *c, **d):
  time.sleep(3)

print '%dsec' % profile(func,1,2)
print '%dsec' % profile(func,1,2,3,4)
print '%dsec' % profile(func,1,2,x=7,y=8)

あらためて考えてみると、この場合、戻り値も返すべきなんじゃないかな。

import time

def profile(__f, *a, **b):
  t = time.time()
  r = __f(*a, **b)
  print time.time() - t
  return r

題意からは関数名は固定されているのですが、任意のinterfaceの任意のメソッド名に対応できるように勝手に拡張しました。Proxyクラスを使用しています。

import java.lang.reflect.InvocationHandler;
import java.lang.reflect.Proxy;
import java.lang.reflect.Method;

public class Profiler {
    private BenchInvocationHandler handler;
    private Object proxy;
    private Object target;

    public Profiler(Class targetInterface, Object myTarget) {
        target = myTarget;
        handler = new BenchInvocationHandler(target);
        proxy = Proxy.newProxyInstance(targetInterface.getClassLoader(), 
                                       new Class[]{targetInterface}, handler);
    }

    public Object getProxy() {
        return proxy;
    }

    public long getEstimatedTime() {
        return handler.getEstimatedTime();
    }
}

class BenchInvocationHandler implements InvocationHandler {
    private Object target;
    private long estimatedTime;

    public BenchInvocationHandler(Object myTarget) {
        target = myTarget;
    }

    public Object invoke(Object proxy, Method method, Object[] args) throws Exception {
        long start = System.nanoTime();
        Object res = method.invoke(target, args);
        estimatedTime = System.nanoTime() - start;
        return res;
    }

    public long getEstimatedTime() {
        return estimatedTime;
    }
}

使い方のサンプルをあげておきます。コンストラクタで測定対象のinterfaceとインスタンスを渡します。getProxyで得られるProxyインスタンスを通常通り呼び出した後でgetEstimatedTimeメソッドの呼び出しで、直前のメソッドの実行時間（ナノ秒）が得られます。

public class Sample implements Runnable {
    public static void main(String[] args) throws Exception {
        Profiler prof = new Profiler(Runnable.class, new Sample());
        Runnable p = (Runnable)prof.getProxy();
        p.run();
        System.out.println(prof.getEstimatedTime());
    }

    public void run() {
        System.out.println("Hello refrelction world.");
    }
}

Squeak Smalltalk で処理の時間を計りたいときは、処理をブロック化（無名関数化）して記述し、それに timeToRun を送信します。

1	[obj func] timeToRun

http://seclan.dll.jp/c99d/c99d02.htm#dt19990405

を参考にマクロで実装。
profileは正確には関数でなくなってしまいました。
ただ、引数の数を気にせず動きます。

#include <stdio.h>
#include <time.h>

#define profile(FUNC, ...) \
    {\
        time_t start, end;\
        \
        start = clock();\
        FUNC(__VA_ARGS__);\
        end = clock();\
        printf("%f\n", (double)(end - start) / CLOCKS_PER_SEC);\
    }

int main()
{
    profile(printf, "%s:%d\n", "hoge", 10);
    profile(puts, "abcdef");
    return 0;
}

インスパイヤして高精度タイマー版を作ってみたり。せっかくだから、#ifdefを使ってWindowsでもLinuxでもOKにしておきました。

#include <stdio.h>
#include <time.h>
#include <sys/types.h>

#ifdef _WIN32
#include <windows.h>		// LARGE_INTEGERに必要
#endif

#ifdef _LINUX
#include <sys/time.h>		// timezoneに必要
#endif

#ifdef _WIN32
#define profile(FUNC, ...) \
    {\
	LARGE_INTEGER liFreq, liBegin, liEnd;\
	double dSec;\
	QueryPerformanceFrequency(&liFreq);\
	QueryPerformanceCounter(&liBegin);\
        FUNC(__VA_ARGS__);\
	QueryPerformanceCounter(&liEnd);\
	dSec	= (double)(liEnd.QuadPart - liBegin.QuadPart)/(double)liFreq.QuadPart;\
        printf("%f sec\n", dSec);\
    }
#endif

#ifdef _LINUX
#define profile(FUNC, ...) \
    {\
	struct timeval tBegin, tEnd;\
	struct timezone tz;\
	double dSec;\
	double dBegin, dEnd;\
	gettimeofday(&tBegin, &tz);\
        FUNC(__VA_ARGS__);\
	gettimeofday(&tEnd, &tz);\
	dBegin	= tBegin.tv_sec + (double)tBegin.tv_usec*1.0e-6;\
	dEnd	= tEnd.tv_sec + (double)tEnd.tv_usec*1.0e-6;\
	dSec	= dEnd - dBegin;\
        printf("%f sec\n", dSec);\
    }
#endif

int main()
{
    profile(printf, "%s:%d\n", "hoge", 10);
    profile(puts, "abcdef");
    return 0;
}

timeという自前の関数があったので、名前だけ変えました。

(defun profile (func &rest args)
  (let ((start (current-time)))
    (apply func args)
    (time-to-seconds (time-subtract (current-time) start))))

オーバーロードされたメソッドがあっても始めに見つかったメソッドのみ対象。

def profile(args: Any*):Unit = {
  val f = getClass.getDeclaredMethods.find(_.getName.startsWith("func")).get
  val start = System.nanoTime
  f.invoke(this, args.map(_.asInstanceOf[AnyRef]).toArray)
  println(System.nanoTime-start + " nano seconds.")
}

def func(i:Int, j:Int):Unit = {
  println(i, j)
}

profile(1,2)

module doukaku;
private import std.stdio;
private import std.date;

d_time profile(void delegate() yield) {
    d_time s = getUTCtime(), diff;
    yield();
    diff = getUTCtime() - s;
    writefln("%f secs", cast(real)diff / TicksPerSecond);
    return diff;
}

void func(int n) {
    writefln("output from func");
    for (int i=0; i<n; i++){};
}

void main() {
    profile(delegate() { func(1000000000); });
}

以前 Higher Order Perl を参考にして Lua で書いたことがあるもの <http://nul.jp/2007/hol/profile> からほぼ転載。「func = profile(func, "func")」とすると func そのものが時間を計測する func に置き換わります。新しい func は同じ引数で使えて同じ戻り値（多値も可）を返しますが、副作用として time["func"] に所要時間を累積していきます（ちょっと題意からは外れるかな）。

time = {}

function profile(func, name)
  return function(...)
    local start = os.clock()
    local result = {func(...)}
    local end_ = os.clock()
    local elasped = end_ - start

    time[name] = time[name] and time[name] + elasped or elasped

    return unpack(result)
  end
end

function func(n)
  print("output from func")
  for i = 1, n, 1 do
    -- do nothing
  end
end

func = profile(func, "func")

func(9999999)

print(time.func)

あー、referenceなんかすっかり忘れてる＞＜

sub profile {
    my $yield = $_[0];
    $start = time();
    &$yield();
    $end = time();
    printf("%s secs\n", $end-$start);
}

sub func {
    my $n = $_[0];
    my $i;
    for ($i=0; $i<$n; $i++){};
}

profile(sub { func(10000000) });

Time::HiRes版

#!/usr/bin/perl

use strict;
use warnings;

use Time::HiRes qw/time/;

sub profile {
    my ($code, @args) = @_;
    my $start = time();
    $code->(@args);
    my $end = time();
    printf("%.4f secs\n", $end - $start);
}

{
    no warnings 'recursion';
    sub factorial {
        my $n = shift;
        ($n > 2) ? $n * factorial($n - 1) : $n;
    }
}

profile(\&factorial, 1000000);

open System;;

let time f =
    let start = DateTime.Now in
    let res = f () in
    let finish = DateTime.Now in
    Console.WriteLine( (finish-start) );
    res;;

let rec fib n =
    if n = 0
    then 1
    elif n = 1
    then 1
    else fib (n-1) + fib (n-2);;

let profile n = time (fun () -> fib n);;

1
2
3

function profile(){
    time func $@
}

Matlabでは、ticで時間を記録し、tocでticからの時間を得ることができます。vararginは可変長引数のため。

function profile(varargin)
  tic;
  func(varargin{:});
  disp(toc);
end

以下のfuncを定義したときの実行結果は

>> profile(3)
    3.0018

となりました。単位は秒のようです。

1
2
3

function func(x)
  pause(x);
end

PHP6非対応

<?php
function profile(/* args */) {
    $func_name = 'func';
    if (!function_exists($func_name)) {
        return false;
    }
    $args = func_get_args();
    $start = microtime();
    call_user_func_array($func_name, $args);
    $end = microtime();
    list($susec, $ssec) = explode(" ", $start);
    list($eusec, $esec) = explode(" ", $end);
    return ($esec - $ssec) + ($eusec - $susec);
}
?>

単純にinvokeしたものを計測。

import java.lang.reflect.Method;

public class Profiler {

    public static long profile(Object o, String methodName, Object... args)
        throws Exception {
        long start = System.currentTimeMillis();
        Method method = getMethod(o.getClass(), methodName);
        method.invoke(o, args);
        return System.currentTimeMillis() - start;
    }

    private static Method getMethod(Class<?> cls, String name)
        throws Exception {
        for (Method m: cls.getDeclaredMethods()) {
            if (m.getName().equals(name)) {
                m.setAccessible(true);
                return m;
            }
        }
        throw new NoSuchMethodException("メソッドがありません");
    }

    private Profiler() {
    }

    /**
     * サンプルメソッド
     */
    private int func(int a, int b) throws Exception {
        Thread.sleep(1000);
        return a + b;
    }

    public static void main(String[] args)
        throws Exception {
        Profiler o = new Profiler();
        System.out.println(Profiler.profile(o, "func", 1, 2) + "ms.");
    }

}

おおお。スゴイ！！

こんなかんじで。
ところで、前回書いた投稿の言語とタグは、そのまま残るとありがたいです。

1
2
3

profile(X,T):-get_time(Before),X,get_time(After),T is After - Before.

:-profile(sleep(1),T),writeln(T).

結果は秒です．
AbusoluteTimingの代わりにTimingでCPU時間になります．

実行例：

In[1]:= func[x_, y_] := 
 Module[{i, s}, s = 0; For[i = 0, i <= x, i++, s = s + i y]; s]

In[2]:= profile[p__] := Module[{time, res},
   {time, res} = AbsoluteTiming[func[p]];
   Print[time];
   res];

In[3]:= func[100000, 2]

Out[3]= 10000100000

In[4]:= profile[100000, 2]

0.7500000

Out[4]= 10000100000

profile[p__] := Module[{time, res},
   {time, res} = AbsoluteTiming[func[p]];
   Print[time];
   res];

とりあえずWHNFにまで簡約する時間(秒)

import System.IO.Unsafe
import System.CPUTime
profile :: a -> a
profile e = unsafePerformIO
          $ do { s <- getCPUTime
               ; r <- return $! e
               ; e <- getCPUTime
               ; putStrLn $ show $ fromInteger (e - s) / fromInteger (10^12)
               ; return r
               }

#916のコードをデコレータに対応させてみた。
デコレータをネストすると、func.__name__でおおもとの関数の名前が取れなくなるが、
リフレクション使っても、おおもとの関数がどこかを判別できない気がする。何か良い方法ないかな。

import time

def profile(func):
	def foo(*a,