benchmark5.md

以下のように TracePoint のブロック内の処理を少しずつ追加してベンチマークをとってみる。

1. トレースなし

2. ブロックのみ

@tracer = TracePoint.new(:a_call, :a_return, :line){|tp|
}

3. skip? メソッド()を追加

@tracer = TracePoint.new(:a_call, :a_return, :line){|tp|
  next if skip?(tp)
}

4. call_identifier_str を取得

@tracer = TracePoint.new(:a_call, :a_return, :line){|tp|
  next if skip?(tp)
  call_identifier_str =
          if tp.defined_class
            minfo(tp)
          else
            "block"
          end
}

5. depth を取得

@tracer = TracePoint.new(:a_call, :a_return, :line){|tp|
  next if skip?(tp)
  
  call_identifier_str =
          if tp.defined_class
            minfo(tp)
          else
            "block"
          end

  depth = caller.size
}

6. :call, :c_call, :b_call のみ配列に挿入

@tracer = TracePoint.new(:a_call, :a_return, :line){|tp|
  next if skip?(tp)
  
  call_identifier_str =
          if tp.defined_class
            minfo(tp)
          else
            "block"
          end

  depth = caller.size

  case tp.event
    when :call, :c_call, :b_call
      append(call_trace_log(depth, call_identifier_str, tp))
    end
  end
}

def append log
  if @prev.size == 4000
    if @cur.size == 4000
      @prev = @cur
      @cur = []
    end
    @cur << log
  else
    @prev << log
  end
end

def call_trace_log depth, name, tp, return_str: nil
  log = {
    depth: depth,
    name: name,
    threadId: Thread.current.instance_variable_get(:@__thread_client_id),
    location: {
      path: tp.path,
      line: tp.lineno
    }
  }
  log[:return] = return_str if return_str
  log
end

7. :return, :c_return, :b_return を配列に挿入

@tracer = TracePoint.new(:a_call, :a_return, :line){|tp|
  next if skip?(tp)
  
  call_identifier_str =
          if tp.defined_class
            minfo(tp)
          else
            "block"
          end

  depth = caller.size

  case tp.event
    when :call, :c_call, :b_call
      append(call_trace_log(depth, call_identifier_str, tp))
    when :return, :c_return, :b_return
      return_str = DEBUGGER__.safe_inspect(tp.return_value, short: true)
      append(call_trace_log(depth, call_identifier_str, tp, return_str: return_str))
    end
  end
}

def append log
  if @prev.size == 4000
    if @cur.size == 4000
      @prev = @cur
      @cur = []
    end
    @cur << log
  else
    @prev << log
  end
end

def call_trace_log depth, name, tp, return_str: nil
  log = {
    depth: depth,
    name: name,
    threadId: Thread.current.instance_variable_get(:@__thread_client_id),
    location: {
      path: tp.path,
      line: tp.lineno
    }
  }
  log[:return] = return_str if return_str
  log
end

8. :line を配列に挿入（全ての処理）

@tracer = TracePoint.new(:a_call, :a_return, :line){|tp|
  next if skip?(tp)
  
  call_identifier_str =
          if tp.defined_class
            minfo(tp)
          else
            "block"
          end

  depth = caller.size

  case tp.event
    when :call, :c_call, :b_call
      append(call_trace_log(depth, call_identifier_str, tp))
    when :return, :c_return, :b_return
      return_str = DEBUGGER__.safe_inspect(tp.return_value, short: true)
      append(call_trace_log(depth, call_identifier_str, tp, return_str: return_str))
    else
      append(line_trace_log(depth, tp))
    end
  end
}

def append log
  if @prev.size == 4000
    if @cur.size == 4000
      @prev = @cur
      @cur = []
    end
    @cur << log
  else
    @prev << log
  end
end

def call_trace_log depth, name, tp, return_str: nil
  log = {
    depth: depth,
    name: name,
    threadId: Thread.current.instance_variable_get(:@__thread_client_id),
    location: {
      path: tp.path,
      line: tp.lineno
    }
  }
  log[:return] = return_str if return_str
  log
end

def line_trace_log depth, tp
  {
    depth: depth,
    threadId: Thread.current.instance_variable_get(:@__thread_client_id),
    location: {
      path: tp.path,
      line: tp.lineno
    }
  }
end

						中央値
1	0.0053439997136592865	0.005103999748826027	0.003889000043272972	0.005276000127196312	0.0052109998650848866	0.0052109998650848866
2	0.006666999775916338	0.007660999894142151	0.007420999929308891	0.004230999853461981	0.00635699974372983	0.006666999775916338
3	0.035503000020980835	0.048353999853134155	0.04328000033274293	0.04008900001645088	0.050484000239521265	0.04328000033274293
4	0.06205399986356497	0.06229200027883053	0.06154699996113777	0.06079799961298704	0.05547900032252073	0.06154699996113777
5	0.07511300034821033	0.0729690003208816	0.06032899999991059	0.07339700032025576	0.06435299990698695	0.0729690003208816
6	0.08247700007632375	0.08081400021910667	0.07778399996459484	0.07730300026014447	0.07956400001421571	0.07956400001421571
7	0.14269599970430136	0.16114800004288554	0.14535299967974424	0.1567480000667274	0.15484199998900294	0.15484199998900294
8	0.15733000030741096	0.15634099999442697	0.16154900006949902	0.15835600020363927	0.16353000001981854	0.15835600020363927

2-1	0.0014559999108314514
3-2	0.03661300055682659
4-3	0.018266999628394842
5-4	0.011422000359743834
6-5	0.006594999693334103
7-6	0.07527799997478724
8-7	0.003514000214636326

ruby/debug#939

ruby/debug#937