DIY Ruby CPU 分析——Part IV

来源:转载

【编者按】 原文链接 作者 Emil Soman,Rubyist,除此之外竟然同时也是艺术家,吉他手,Garden City RubyConf 组织者。本文是 DIY Ruby CPU Profiling 的第四部分,本文系OneAPM 工程师编译整理。

原文链接: http://crypt.codemancers.com/posts/2015-07-18-diy-ruby-cpu-profiling-part-iv/ 在第一部分我们了解了 CPU 分析器是如何工作的,在第二部分我们学习了如何通过 CPU time 和 Wall time 测量程序的执行时间,在第三部分我们学习了如何用 Ruby 的 TracePoint API 来跟踪 Ruby VM 中的方法调用和返回。我们还着手建立了自己的 DiyProf gem. 建议在继续之前先阅读这些。在这部分我们将利用通过 TracePoint API 收集到的数据创造一个简单的可视化调用图。

Part IV. 调用图

在第三部分,我们通过 Ruby 的 TracePoint API 来展示方法的调用和返回 trace. 如果可以解析这些 trace 并通过它们制作调用图,应该会更有用。调用图是用一种树形图来代表方法调用,进行基本的可视化。就像下图: 上图告诉我们 other_method 从 inner_method{1,2,3} 中调用了三个方法,而 inner_method_3 调用了另一个名为 inner_most_method 的方法。

Graphviz 和 DOT 语言

Graphviz 是一种图形可视化工具,可以生成文本格式的图形说明,并生成 PDF 等多种格式的图表。为了用文本格式描述图形,Graphviz 使用一种名为 DOT 的语言,通过简单的声明描述节点和节点之间的关系。在继续之前,先确保安装了 Graphviz 且 dot 命令在 $PATH 中可用。遵循安装步骤的官方文件即可。 举个例子,

digraph graph_name { a -> b -> c; b -> d;}

保存上述几条作为一个样本,dot 并运行下列命令。

dot -Tpdf sample.dot -o graph.pdf

上述命令将会生成一个直观的图,如下所示: 还有另一种代表图的方法,通过分离节点和关系,如下:

digraph graph_name { <nodes> <connections>}

因此下列 DOT 符号代表同样的图:

digraph graph_name { a; b; c; d; a -> b; b -> c; b -> d;}

还可以为节点和关系添加附加标签。

digraph graph_name { a [label="a /n foo: bar"]; b [label="b /n foo: baz"] a -> b [label="xyz"];}

上述 DOT 代码代表下图:

Graphviz 调用图

我们想要为我们的 DiyProf gem 创造一个报告类,通过它来持续收集所有方法调用并创造一个 DOT 文件来代表调用图。 我们将在进入 DotReporter 类下面添加一个 record 方法,DotReporter 类能够在调用发生时推送方法信息进堆,在方法返回时从堆中抛出方法信息。当方法信息被从堆中抛出,它在堆中花费的时间则被记录,并且向调用树添加方法调用信息。看下列代码:

module DiyProf # Struct that will hold a method name and a timestamp CallInfo = Struct.new(:name, :time) class DotReporter def initialize # A stack for pushing/popping methods when methods get called/returned @call_stack = [] # Nodes for all methods @methods = {} # Connections between the nodes @calls = {} end def record(event, method_name, time) case event when :call @call_stack << CallInfo.new(method_name, time) when :return # Return cannot be the first event in the call stack return if @call_stack.empty? method = @call_stack.pop # Set execution time of method in call info method.time = time - method.time add_method_to_call_tree(method) end end endend ```# Struct that holds the time spent in a method# and the total number of times a method was calledMethodInfo = Struct.new(:count, :total_time, :self_time)def add_method_to_call_tree(method) # Add method as a node to the call graph @methods[method.name] ||= MethodInfo.new(0, 0, 0) # Update total time(spent inside the method and methods called inside this method) @methods[method.name].total_time += method.time # Update self time(spent inside the method and not methods called inside this method) # This will be subtracted when children are added to the graph @methods[method.name].self_time += method.time # Update total no of times the method was called @methods[method.name].count += 1 # If the method has a parent in the call stack # Add a connection from the parent node to this method if parent = @call_stack.last @calls[parent.name] ||= {} @calls[parent.name][method.name] ||= 0 @calls[parent.name][method.name] += 1 # Take away self time of parent @methods[parent.name] ||= MethodInfo.new(0, 0, 0) @methods[parent.name].self_time -= method.time endend

现在我们在 @methods 和 @calls 中都有节点和关系了,可以但不是必须要生成一个如下的文件:

digraph G { <graph_nodes> <graph_links>}

下面是将在 @methods 和 @calls 中出现的代码,准备如下的 DOT 文件:

def dot_notation dot = %Q( digraph G { #{graph_nodes} #{graph_links} } )enddef graph_nodes nodes = "" @methods.each do |name, method_info| nodes << "#{name} [label=/"#{name}//ncalls: #{method_info.count}//ntotal time: #{method_info.total_time}//nself time: #{method_info.self_time}/"];/n" end nodesenddef graph_links links = "" @calls.each do |parent, children| children.each do |child, count| links << "#{parent} -> #{child} [label=/" #{count}/"];/n" end end linksend

在 github repo 上检查 lib/diy_prof/dot_reporter.rb 文件,看看它们是怎样彼此配合的。我们同时还需要利用规定的报告类在第三部分写过的 Tracer 类中做一些改变:

module DiyProf class Tracer # We'll need to initialize the Tracer with DotReporter.new def initialize(reporter) @reporter = reporter @tracepoints = [:call, :return].collect do |event| TracePoint.new(event) do |trace| # Use the reporter instead of just printing the traces reporter.record(event, trace.method_id, cpu_time) end end end ... # New method added to collect the report after profiling def result @reporter.result end endend

现在我们的 tracer 能够生成 DOT 格式的报告了,我们将它用在先前部分中写过的样本程序上:

def main 3.times do find_many_square_roots find_many_squares endenddef find_many_square_roots 5000.times{|i| Math.sqrt(i)}enddef find_many_squares 5000.times{|i| i**2 }endDiyProf.start_profiling main result = DiyProf.stop_profilingrequire 'tempfile' f = Tempfile.open('dot') f.write result f.close system("dot -Tpdf #{f.path} -o call_graph.pdf")

我们将得到一个如下所示的调用图: 恭喜你已经进行到这一步,检查拥有完整代码的 github repo.

额外令人开心的事!

如果能基于本身或方法总时间区分节点大小岂不是很酷?DOT 语法允许节点和 edges 拥有一系列属性。就像我们可以用 size 和 fontsize 属性来区分节点和节点内的内容。我将把如何用过这些来使最重要的方法在调用图中着重显示,这个问题将留给你们。

概括

我们学习了关于 Graphviz 和 DOT 语言及如何它们创造基于 Ruby TracePoint API 收集到的数据的调用图表。在第五部分,我们将着手建立一个简单的 RUby 分析器,尤其会学到一些基本的 C 里的信号中断和处理。感谢阅读,如果想要获取关于 DIY CPU 分析系列的最新博客内容,请关注我们的推特 @codemancershq.

OneAPM for Ruby和监控,包括代码级别性能问题的可见性、性能瓶颈的快速识别与追溯、真实用户体验监控、服务器监控和端到端的应用性能管理。 想阅读更多技术文章,请访问OneAPM 官方博客。



分享给朋友:
您可能感兴趣的文章:
随机阅读: