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)