【编者按】原文链接 作者 Emil Soman,Rubyist,除此之外竟然同时也是艺术家,吉他手,Garden City RubyConf 组织者。本文是 DIY Ruby CPU Profiling 的第四部分,本文系 OneAPM 工程师编译整理。
在第一部分我们了解了 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
end
end
```
# Struct that holds the time spent in a method
# and the total number of times a method was called
MethodInfo = 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
end
end
现在我们在@methods
和@calls
中都有节点和关系了,可以但不是必须要生成一个如下的文件:
digraph G {
<graph_nodes>
<graph_links>
}
下面是将在@methods
和@calls
中出现的代码,准备如下的 DOT 文件:
def dot_notation
dot = %Q(
digraph G {
#{graph_nodes}
#{graph_links}
}
)
end
def 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
nodes
end
def graph_links
links = ""
@calls.each do |parent, children|
children.each do |child, count|
links << "#{parent} -> #{child} [label=\" #{count}\"];\n"
end
end
links
end
在 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
end
end
现在我们的 tracer 能够生成 DOT 格式的报告了,我们将它用在先前部分中写过的样本程序上:
def main
3.times do
find_many_square_roots
find_many_squares
end
end
def find_many_square_roots
5000.times{|i| Math.sqrt(i)}
end
def find_many_squares
5000.times{|i| i**2 }
end
DiyProf.start_profiling
main
result = DiyProf.stop_profiling
require '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.
原文链接:http://crypt.codemancers.com/posts/2015-07-18-diy-ruby-cpu-profiling-part-iv/
OneAPM for Ruby监控,包括代码级别性能问题的可见性、性能瓶颈的快速识别与追溯、真实用户体验监控、服务器监控和端到端的应用性能管理。 想阅读更多技术文章,请访问 OneAPM 官方博客。
小布丁
写的棒棒哒……
小布丁
写的真可以……
wuxin
受教了……
爱码物联
博客使用……
yancy_01
很喜欢文字的描述,特别是理论性质的,相比于代码,理论知识更加有意思,谢谢分享……
阿萨德
台风压力测试系统http://taifeng.yunyc.top/……
台风DDOS网页版
台风压力测试系统http://taifeng.yunyc.top/……
台风DDOS网页版
台风压力测试系统http://taifeng.yunyc.top/网站测压IP服务器……
台风DDOS网页版
台风压力测试系统http://taifeng.yunyc.top/网站测压IP服务器……
笨鸟先飞
天天向上www.tiantianxsh.com……