def main():
"""Main sequence"""
analyser = Analyser(config=ProfilingConfig)
data = import_all(config=ProfilingConfig)
analyser.run(data)
del analyser
del data
profiler = Profile()
tracemalloc.start(10)
time1 = tracemalloc.take_snapshot()
profiler.runcall(test)
time2 = tracemalloc.take_snapshot()
time_stats = Stats(profiler)
time_stats.strip_dirs()
time_stats.sort_stats('cumulative')
print("\n===Time Profiler Stats===\n")
time_stats.print_stats(TOP_STATS)
print("\n===Time Profiler Callers===\n")
time_stats.print_callers(TOP_STATS)
memory_stats = time2.compare_to(time1, 'lineno')
print("\n===Memory Profiler Callers===\n")
for stat in memory_stats[:3]:
print(stat)
print("\n===Top Memory Consumer===\n")
top = memory_stats[0]
print('\n'.join(top.traceback.format()))
def inner(*args, **kwargs):
pro = Profile()
pro.runcall(func, *args, **kwargs)
stats = Stats(pro)
stats.strip_dirs()
stats.sort_stats(field)
print("Profile for {}()".format(func.__name__))
stats.print_stats()
stats.print_callers()
def example_three():
"""
20242 function calls in 0.063 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.063 0.063 item_58_profile.py:140(my_program)
20 0.002 0.000 0.063 0.003 item_58_profile.py:130(first_func)
20200 0.061 0.000 0.061 0.000 item_58_profile.py:124(my_utility)
20 0.000 0.000 0.001 0.000 item_58_profile.py:135(second_func)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
-notes for Nick
- you may profile your program only to find that a common utility
function is responsible for majority of the execution time.
- default output from the profiler doesn't show how the utility
function is called by many different parts of your program.
- 'my_utility' function is evidently the source of most execution time,
but it is not immediately obvious why that function is called so many times.
---- Callers -----
Ordered by: cumulative time
Function was called by...
ncalls tottime cumtime
item_58_profile.py:140(my_program) <-
item_58_profile.py:130(first_func) <- 20 0.002 0.062 item_58_profile.py:140(my_program)
item_58_profile.py:124(my_utility) <- 20000 0.061 0.061 item_58_profile.py:130(first_func)
200 0.001 0.001 item_58_profile.py:135(second_func)
item_58_profile.py:135(second_func) <- 20 0.000 0.001 item_58_profile.py:140(my_program)
{method 'disable' of '_lsprof.Profiler' objects} <-
"""
profiler = Profile()
profiler.runcall(my_program)
# to extract statistics about the 'test' function's performance, we use pstats
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_stats()
print('\n---- Callers -----\n')
# to see how many times a function is called
stats.print_callers()
def print_stats(profiler, printCallers=False):
from pstats import Stats
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
if printCallers is True:
stats.print_callers()
else:
stats.print_stats()
def demo():
f = lambda x: x
profiler = Profile()
profiler.runcall(f)
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_stats()
stats.print_callers()
stats.print_callees()
def filter(self, execution_func, prof_arg = None):
import cProfile as profile
from pstats import Stats
tmpfile = tempfile.NamedTemporaryFile()
try:
file, line = prof_arg.split(':')
line, func = line.split('(')
func = func.strip(')')
except:
file = line = func = None
try:
profile.runctx('execution_func()',
globals(), locals(), tmpfile.name)
out = StringIO()
stats = Stats(tmpfile.name, stream=out)
stats.sort_stats('time', 'calls')
def parse_table(t, ncol):
table = []
for s in t:
t = [x for x in s.split(' ') if x]
if len(t) > 1:
table += [t[:ncol-1] + [' '.join(t[ncol-1:])]]
return table
def cmp(n):
def _cmp(x, y):
return 0 if x[n] == y[n] else 1 if x[n] < y[n] else -1
return _cmp
if not file:
stats.print_stats()
stats_str = out.getvalue()
statdata = stats_str.split('\n')
headers = '\n'.join(statdata[:6])
table = parse_table(statdata[6:], 6)
from r2.lib.pages import Profiling
res = Profiling(header = headers, table = table,
path = request.path).render()
return [unicode(res)]
else:
query = "%s:%s" % (file, line)
stats.print_callees(query)
stats.print_callers(query)
statdata = out.getvalue()
data = statdata.split(query)
callee = data[2].split('->')[1].split('Ordered by')[0]
callee = parse_table(callee.split('\n'), 4)
callee.sort(cmp(1))
callee = [['ncalls', 'tottime', 'cputime']] + callee
i = 4
while '<-' not in data[i] and i < len(data): i+= 1
caller = data[i].split('<-')[1]
caller = parse_table(caller.split('\n'), 4)
caller.sort(cmp(1))
caller = [['ncalls', 'tottime', 'cputime']] + caller
from r2.lib.pages import Profiling
res = Profiling(header = prof_arg,
caller = caller, callee = callee,
path = request.path).render()
return [unicode(res)]
finally:
tmpfile.close()
a + b
def first_func():
for _ in range(1000):
my_utility(4, 5)
def second_func():
for _ in range(10):
my_utility(1, 3)
def my_program():
for _ in range(20):
first_func()
second_func()
test = lambda: my_program()
from cProfile import Profile
profiler = Profile()
profiler.runcall(test)
from pstats import Stats
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_callers()
# 1 0.000 0.000 3.648 3.648 item_58_profile_before_optimizing.py:190(my_program) # 20 2.005 0.100 3.612 0.181 item_58_profile_before_optimizing.py:180(first_func) # 2020000 1.623 0.000 1.623 0.000 item_58_profile_before_optimizing.py:173(my_utility) # 20 0.020 0.001 0.035 0.002 item_58_profile_before_optimizing.py:185(second_func) # 1 0.000 0.000 0.000 0.000 :0(setprofile) # 0 0.000 0.000 profile:0(profiler) # The my_utility function is clearly the source of most execution time, but # it's not immediately obvious why that function is called so much. If you # search through the program's code, you'll find multiple call sites for # my_utility and still be confused. # To deal with this, the Python profiler provides a way of seeing which # callers contributed to the profiling information of each function. stats_my.print_callers() # This profiler statistics table shows functions called on the left and who # was responsible for making the call on the right. Here, it's clear that # my_utility is most used by first_func: # Ordered by: cumulative time # # Function was called by... # profile:0(<function my_program at 0x7f2b11841400>) <- profile:0(profiler)(1) 0.000 # item_58_profile_before_optimizing.py:190(my_program) <- profile:0(<function my_program at 0x7f2b11841400>)(1) 3.869 # item_58_profile_before_optimizing.py:180(first_func) <- item_58_profile_before_optimizing.py:190(my_program)(20) 3.869 # item_58_profile_before_optimizing.py:173(my_utility) <- item_58_profile_before_optimizing.py:180(first_func)(2000000) 3.831 # item_58_profile_before_optimizing.py:185(second_func)(20000) 0.037 # item_58_profile_before_optimizing.py:185(second_func) <- item_58_profile_before_optimizing.py:190(my_program)(20) 3.869 # :0(setprofile) <- profile:0(<function my_program at 0x7f2b11841400>)(1) 3.869
"""
Created on Jan 13, 2014
@Company: PBS Biotech
@Author: Nathan Starkweather
"""
from pstats import Stats
stats_file = "C:\\Users\\PBS Biotech\\Documents\\Personal\\PBS_Office\\MSOffice\\officelib\\pbslib\\test\\profile2.txt"
from datetime import datetime
s = Stats(stats_file)
s.strip_dirs()
s.sort_stats('time')
s.print_callers(0.1)
for i in range(100):
c += a * b
def first_func():
for _ in range(1000):
my_utility(4, 5)
def second_func():
for _ in range(10):
my_utility(1, 3)
def my_program():
for _ in range(20):
first_func()
second_func()
profiler = Profile()
profiler.runcall(my_program)
stats = Stats(profiler, stream=STDOUT)
stats.strip_dirs()
stats.sort_stats('cumulative')
print('함수 테스트')
stats.print_stats()
stats = Stats(profiler, stream=STDOUT)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_callers() # 호출된 함수를 왼쪽에 보여주고, 누가 호출하는지를 오른쪽에 보여준다
# from cProfile import Profile
# profiler = Profile()
# profiler.runcall(test)
# import sys
# from pstats import Stats
# stats = Stats(profiler)
# stats.strip_dirs()
# stats.sort_stats('cumulative')
# stats.print_stats()
#
from bisect import bisect_left
def insert_value(array, value):
i = bisect_left(array, value)
array.insert(i, value)
from cProfile import Profile
profiler = Profile()
profiler.runcall(test)
import sys
from pstats import Stats
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_stats()
stats.print_callers()
s=Stats(cprofile.out)
s=Stats('cprofile.out')
s
print_stats(s)
import pstats
s.print_stats()
s.print_caller()
s.prim_calls()
s.print_callees()
s.print_call_line()
s.strip_dirs()
s=s.strip_dirs()
s.sort_stats
s.sort_stats()
s=s.sort_stats('cumulative')
s.print_callers()
get_ipython().run_line_magic('logstart', '')
s.print_callers()
get_ipython().run_line_magic('run', '-m cProfile -s cumulative 03_ml_data.py >cprofile.out 2>&1')
get_ipython().run_line_magic('run', '-m cProfile -s cumulative 03_ml_data.py 2>cprofile.out')
get_ipython().run_line_magic('capture', 'cprofile.out')
get_ipython().run_cell_magic('capture', 'cprofile.out', 'run -m cProfile -s cumulative 03_ml_data.py')
run -m cProfile -s cumulative 03_ml_data.py
cprofile.out
get_ipython().run_cell_magic('capture', 'cprofile_out', 'run -m cProfile -s cumulative 03_ml_data.py')
run -m cProfile -s cumulative 03_ml_data.py
cprofile_out.show()
get_ipython().run_cell_magic('capture', 'cprofile_out', '%run -m cProfile -s cumulative 03_ml_data.py')
get_ipython().run_line_magic('run', '-m cProfile -s cumulative 03_ml_data.py')
cprofile_out.show()
print(cprofile_out.show(),file=open('cprofile.out','w'))
def filter(self, execution_func, prof_arg=None):
# put thie imports here so the app doesn't choke if profiling
# is not present (this is a debug-only feature anyway)
import cProfile as profile
from pstats import Stats
tmpfile = tempfile.NamedTemporaryFile()
try:
file, line = prof_arg.split(":")
line, func = line.split("(")
func = func.strip(")")
except:
file = line = func = None
try:
profile.runctx("execution_func()", globals(), locals(), tmpfile.name)
out = StringIO()
stats = Stats(tmpfile.name, stream=out)
stats.sort_stats("time", "calls")
def parse_table(t, ncol):
table = []
for s in t:
t = [x for x in s.split(" ") if x]
if len(t) > 1:
table += [t[: ncol - 1] + [" ".join(t[ncol - 1 :])]]
return table
def cmp(n):
def _cmp(x, y):
return 0 if x[n] == y[n] else 1 if x[n] < y[n] else -1
return _cmp
if not file:
stats.print_stats()
stats_str = out.getvalue()
statdata = stats_str.split("\n")
headers = "\n".join(statdata[:6])
table = parse_table(statdata[6:], 6)
from r2.lib.pages import Profiling
res = Profiling(header=headers, table=table, path=request.path).render()
return [unicode(res)]
else:
query = "%s:%s" % (file, line)
stats.print_callees(query)
stats.print_callers(query)
statdata = out.getvalue()
data = statdata.split(query)
callee = data[2].split("->")[1].split("Ordered by")[0]
callee = parse_table(callee.split("\n"), 4)
callee.sort(cmp(1))
callee = [["ncalls", "tottime", "cputime"]] + callee
i = 4
while "<-" not in data[i] and i < len(data):
i += 1
caller = data[i].split("<-")[1]
caller = parse_table(caller.split("\n"), 4)
caller.sort(cmp(1))
caller = [["ncalls", "tottime", "cputime"]] + caller
from r2.lib.pages import Profiling
res = Profiling(header=prof_arg, caller=caller, callee=callee, path=request.path).render()
return [unicode(res)]
finally:
tmpfile.close()
def tearDown(self):
from pstats import Stats
p = Stats(self.pr)
p.sort_stats('cumtime')
# p.print_stats()
p.print_callers('heavy_function')
def first_func():
for _ in range(1000):
my_utility(4, 5)
def second_func():
for _ in range(10):
my_utility(1, 3)
def my_program():
for _ in range(20):
first_func()
second_func()
profiler = Profile()
profiler.runcall(my_program)
stats = Stats(profiler, stream=STDOUT)
stats.strip_dirs()
stats.sort_stats('cumulative')
print('함수 테스트')
stats.print_stats()
stats = Stats(profiler, stream=STDOUT)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_callers() # 호출된 함수를 왼쪽에 보여주고, 누가 호출하는지를 오른쪽에 보여준다
class CProfileVStats(object):
"""Wrapper around pstats.Stats class."""
def __init__(self, output_file):
self.output_file = output_file
self.obj = Stats(output_file)
self.reset_stream()
def reset_stream(self):
self.obj.stream = StringIO()
def read(self):
value = self.obj.stream.getvalue()
self.reset_stream()
# process stats output
value = self._process_header(value)
value = self._process_lines(value)
return value
IGNORE_FUNC_NAMES = ['function', '']
STATS_LINE_REGEX = r'(.*)\((.*)\)$'
HEADER_LINE_REGEX = r'ncalls|tottime|cumtime'
DEFAULT_SORT_ARG = 'cumulative'
SORT_ARGS = {
'ncalls': 'calls',
'tottime': 'time',
'cumtime': 'cumulative',
'filename': 'module',
'lineno': 'nfl',
}
@classmethod
def _process_header(cls, output):
result = []
lines = output.splitlines(True)
for idx, line in enumerate(lines):
match = re.search(cls.HEADER_LINE_REGEX, line)
if match:
for key, val in cls.SORT_ARGS.iteritems():
url_link = template(
"<a href='{{ url }}'>{{ key }}</a>",
url=get_href(SORT_KEY, val),
key=key)
line = line.replace(key, url_link)
lines[idx] = line
break
return ''.join(lines)
@classmethod
def _process_lines(cls, output):
lines = output.splitlines(True)
for idx, line in enumerate(lines):
match = re.search(cls.STATS_LINE_REGEX, line)
if match:
prefix = match.group(1)
func_name = match.group(2)
if func_name not in cls.IGNORE_FUNC_NAMES:
url_link = template(
"<a href='{{ url }}'>{{ func_name }}</a>",
url=get_href(FUNC_NAME_KEY, func_name),
func_name=func_name)
lines[idx] = template(
"{{ prefix }}({{ !url_link }})\n",
prefix=prefix, url_link=url_link)
return ''.join(lines)
def show(self, restriction=''):
self.obj.print_stats(restriction)
return self
def show_callers(self, func_name):
self.obj.print_callers(func_name)
return self
def show_callees(self, func_name):
self.obj.print_callees(func_name)
return self
def sort(self, sort=''):
sort = sort or self.DEFAULT_SORT_ARG
self.obj.sort_stats(sort)
return self
def filter(self, execution_func, prof_arg = None):
# put thie imports here so the app doesn't choke if profiling
# is not present (this is a debug-only feature anyway)
import cProfile as profile
from pstats import Stats
tmpfile = tempfile.NamedTemporaryFile()
file = line = func = None
sort_order = 'time'
if prof_arg:
tokens = prof_arg.split(',')
else:
tokens = ()
for token in tokens:
if token == "cum":
sort_order = "cumulative"
elif token == "name":
sort_order = "name"
else:
try:
file, line = prof_arg.split(':')
line, func = line.split('(')
func = func.strip(')')
except:
file = line = func = None
try:
profile.runctx('execution_func()',
globals(), locals(), tmpfile.name)
out = StringIO()
stats = Stats(tmpfile.name, stream=out)
stats.sort_stats(sort_order, 'calls')
def parse_table(t, ncol):
table = []
for s in t:
t = [x for x in s.split(' ') if x]
if len(t) > 1:
table += [t[:ncol-1] + [' '.join(t[ncol-1:])]]
return table
def cmp(n):
def _cmp(x, y):
return 0 if x[n] == y[n] else 1 if x[n] < y[n] else -1
return _cmp
if not file:
stats.print_stats()
stats_str = out.getvalue()
statdata = stats_str.split('\n')
headers = '\n'.join(statdata[:6])
table = parse_table(statdata[6:], 6)
from r2.lib.pages import Profiling
res = Profiling(header = headers, table = table,
path = request.path).render()
return [unicode(res)]
else:
query = "%s:%s" % (file, line)
stats.print_callees(query)
stats.print_callers(query)
statdata = out.getvalue()
data = statdata.split(query)
callee = data[2].split('->')[1].split('Ordered by')[0]
callee = parse_table(callee.split('\n'), 4)
callee.sort(cmp(1))
callee = [['ncalls', 'tottime', 'cputime']] + callee
i = 4
while '<-' not in data[i] and i < len(data): i+= 1
caller = data[i].split('<-')[1]
caller = parse_table(caller.split('\n'), 4)
caller.sort(cmp(1))
caller = [['ncalls', 'tottime', 'cputime']] + caller
from r2.lib.pages import Profiling
res = Profiling(header = prof_arg,
caller = caller, callee = callee,
path = request.path).render()
return [unicode(res)]
finally:
tmpfile.close()
#!/usr/bin/env python3
import argparse
from pstats import Stats
parser = argparse.ArgumentParser()
parser.add_argument('filename', type=str, nargs='?', default='train.prof')
args = parser.parse_args()
s = Stats(args.filename)
s.sort_stats('time')
s.print_stats(0.05)
s.print_callers(0.01)
