我正在尝试分析一个调用其他函数的函数。我按如下方式调用分析器：
from mymodule import foo
def start():
# ...
foo()
import cProfile as profile
profile.run('start()', output_file)
p = pstats.Stats(output_file)
print "name: "
print p.sort_stats('name')
print "all stats: "
p.print_stats()
print "cumulative (top 10): "
p.sort_stats('cumulative').print_stats(10)
我发现分析器说所有时间都花在了 mymodule 的函数“foo()”上，而不是把它分解成子函数 foo() 调用，这是我想看到的。如何让探查器报告这些功能的性能？
谢谢。
首先，我想说我无法复制提问者的问题。分析器（在 py2.7 中）肯定会下降到被调用的函数和方法中。（py3.6 的文档看起来相同，但我没有在 py3 上测试过。）我的猜测是，通过将其限制为前 10 个返回值，按累积时间排序，其中前 N 个是非常高级的函数，称为最少的时间，并且调用的函数foo()从列表的底部掉了下来。
我决定使用一些大数字进行测试。这是我的测试代码：
# file: mymodule.py
import math
def foo(n = 5):
for i in xrange(1,n):
baz(i)
bar(i ** i)
def bar(n):
for i in xrange(1,n):
e = exp200(i)
print "len e: ", len("{}".format(e))
def exp200(n):
result = 1
for i in xrange(200):
result *= n
return result
def baz(n):
print "{}".format(n)
以及包含文件（与 Asker 的非常相似）：
# file: test.py
from mymodule import foo
def start():
# ...
foo(8)
OUTPUT_FILE = 'test.profile_info'
import pstats
import cProfile as profile
profile.run('start()', OUTPUT_FILE)
p = pstats.Stats(OUTPUT_FILE)
print "name: "
print p.sort_stats('name')
print "all stats: "
p.print_stats()
print "cumulative (top 10): "
p.sort_stats('cumulative').print_stats(10)
print "time (top 10): "
p.sort_stats('time').print_stats(10)
注意最后一行。我添加了一个按 排序的视图，它是函数“不包括调用子函数的时间”所time花费的总时间。我发现这个视图更有用，因为它倾向于支持正在执行实际工作的函数，并且可能需要优化。
这是提问者正在使用的部分结果（cumulative-sorted ）：
cumulative (top 10):
Thu Mar 24 21:26:32 2016 test.profile_info
2620840 function calls in 76.039 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 76.039 76.039 <string>:1(<module>)
1 0.000 0.000 76.039 76.039 test.py:5(start)
1 0.000 0.000 76.039 76.039 /Users/jhazen/mymodule.py:4(foo)
7 10.784 1.541 76.039 10.863 /Users/jhazen/mymodule.py:10(bar)
873605 49.503 0.000 49.503 0.000 /Users/jhazen/mymodule.py:15(exp200)
873612 15.634 0.000 15.634 0.000 {method 'format' of 'str' objects}
873605 0.118 0.000 0.118 0.000 {len}
7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:21(baz)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
看看这个显示中的前 3 个函数是如何只被调用一次的。让我们看一下time-sorted 视图：
time (top 10):
Thu Mar 24 21:26:32 2016 test.profile_info
2620840 function calls in 76.039 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
873605 49.503 0.000 49.503 0.000 /Users/jhazen/mymodule.py:15(exp200)
873612 15.634 0.000 15.634 0.000 {method 'format' of 'str' objects}
7 10.784 1.541 76.039 10.863 /Users/jhazen/mymodule.py:10(bar)
873605 0.118 0.000 0.118 0.000 {len}
7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:21(baz)
1 0.000 0.000 76.039 76.039 /Users/jhazen/mymodule.py:4(foo)
1 0.000 0.000 76.039 76.039 test.py:5(start)
1 0.000 0.000 76.039 76.039 <string>:1(<module>)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
现在排名第一的条目是有道理的。显然，通过重复乘法将某事物提高到 200 次方是一种“幼稚”的策略。让我们替换它：
def exp200(n):
return n ** 200
结果：
time (top 10):
Thu Mar 24 21:32:18 2016 test.profile_info
2620840 function calls in 30.646 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
873612 15.722 0.000 15.722 0.000 {method 'format' of 'str' objects}
7 9.760 1.394 30.646 4.378 /Users/jhazen/mymodule.py:10(bar)
873605 5.056 0.000 5.056 0.000 /Users/jhazen/mymodule.py:15(exp200)
873605 0.108 0.000 0.108 0.000 {len}
7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:18(baz)
1 0.000 0.000 30.646 30.646 /Users/jhazen/mymodule.py:4(foo)
1 0.000 0.000 30.646 30.646 test.py:5(start)
1 0.000 0.000 30.646 30.646 <string>:1(<module>)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
这是一个很好的时间改进。现在str.format()是我们最严重的罪犯。我添加了一行bar()来打印数字的长度，因为我的第一次尝试（只是计算数字而不用它做任何事情）得到了优化，而我试图避免这种情况（打印数字，它变得非常快）似乎它可能会阻塞 I/O，所以我在打印数字的长度时做出了妥协。嘿，那是 base-10 日志。让我们试试：
def bar(n):
for i in xrange(1,n):
e = exp200(i)
print "log e: ", math.log10(e)
结果：
time (top 10):
Thu Mar 24 21:40:16 2016 test.profile_info
1747235 function calls in 11.279 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
7 6.082 0.869 11.279 1.611 /Users/jhazen/mymodule.py:10(bar)
873605 4.996 0.000 4.996 0.000 /Users/jhazen/mymodule.py:15(exp200)
873605 0.201 0.000 0.201 0.000 {math.log10}
7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:18(baz)
1 0.000 0.000 11.279 11.279 /Users/jhazen/mymodule.py:4(foo)
7 0.000 0.000 0.000 0.000 {method 'format' of 'str' objects}
1 0.000 0.000 11.279 11.279 test.py:5(start)
1 0.000 0.000 11.279 11.279 <string>:1(<module>)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
嗯，bar()即使没有str.format(). 让我们摆脱那个打印：
def bar(n):
z = 0
for i in xrange(1,n):
e = exp200(i)
z += math.log10(e)
return z
结果：
time (top 10):
Thu Mar 24 21:45:24 2016 test.profile_info
1747235 function calls in 5.031 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
873605 4.487 0.000 4.487 0.000 /Users/jhazen/mymodule.py:17(exp200)
7 0.440 0.063 5.031 0.719 /Users/jhazen/mymodule.py:10(bar)
873605 0.104 0.000 0.104 0.000 {math.log10}
7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:20(baz)
1 0.000 0.000 5.031 5.031 /Users/jhazen/mymodule.py:4(foo)
7 0.000 0.000 0.000 0.000 {method 'format' of 'str' objects}
1 0.000 0.000 5.031 5.031 test.py:5(start)
1 0.000 0.000 5.031 5.031 <string>:1(<module>)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
现在看起来做实际工作的东西是最忙的功能，所以我认为我们已经完成了优化。
希望有帮助！
您需要p.print_callees()获得方法调用的分层分解。输出很容易解释：在左侧列中，您可以找到您感兴趣的函数，例如foo()，然后转到右侧列显示所有调用的子函数及其范围内的总时间和累积时间。还包括这些子调用的细目等。
也许您遇到了类似的问题，所以我将在这里描述我的问题。我的分析代码如下所示：
def foobar():
import cProfile
pr = cProfile.Profile()
pr.enable()
for event in reader.events():
baz()
# and other things
pr.disable()
pr.dump_stats('result.prof')
最终的分析输出只包含events()调用。我花了很多时间才意识到我有空循环分析。当然，foobar()来自客户端代码的调用不止一次，但有意义的分析结果已被最后一次空循环调用覆盖。