Ticket #13361: trac_13361_startuptime.patch

File trac_13361_startuptime.patch, 6.7 KB (added by vbraun, 9 years ago)

Improved patch

  • sage-startuptime.py

    # HG changeset patch
    # User Volker Braun <vbraun@stp.dias.ie>
    # Date 1344876086 14400
    # Node ID 50ee7edbb0484710f05808947ccd5e4d174a0b74
    # Parent  1dd3cffdc684fd86f93aa51b18672020b79cfb25
    Report startuptime exclusive children instead of inclusive
    
    diff --git a/sage-startuptime.py b/sage-startuptime.py
    a b  
    11#!/usr/bin/env python
    2 ###########################################################
    3 # Based on a script by Andrew Dalke:
     2
     3########################################################################
     4# Originally based on a script by Andrew Dalke:
    45#    http://projects.scipy.org/pipermail/numpy-discussion/2008-July/035415.html
    56#
    6 # From: Andrew Dalke <dalke@dalkescientific.com>
    7 # Date: Sun, Jul 6, 2008 at 10:07 AM
    8 # To: Mike Hansen <mhansen@gmail.com>
    9 # "This work written by Andrew Dalke and released into the public
    10 # domain in 2008.  No copyright protection is asserted."
    11 #   
    12 # Included in Sage by Mike Hansen and William Stein
    13 ###########################################################
     7# 2012: Total rewrite by Volker Braun
     8########################################################################
    149
    1510
     11########################################################################
     12#       Copyright (C) 2012 Volker Braun <vbraun.name@gmail.com>
     13#
     14#  Distributed under the terms of the GNU General Public License (GPL)
     15#
     16#                  http://www.gnu.org/licenses/
     17########################################################################
     18
     19import sys
    1620import time
     21import gc
    1722
    18 seen = set()
    19 import_order = []
    20 elapsed_times = {}
    21 global_level = 0
     23cmdline_args = sys.argv[2:]
     24have_cmdline_args = (len(cmdline_args) > 0)
     25
     26direct_children_time = 0
     27import_counter = 0
    2228parent = None
    23 children = {}
     29index_to_parent = dict()
     30all_modules = dict()
    2431
    2532def new_import(name, globals={}, locals={}, fromlist=[], level=-1):
    26      global global_level, parent
    27      if name in seen:
    28          return old_import(name, globals, locals, fromlist)
    29      seen.add(name)
    30      import_order.append((name, global_level, parent))
     33     """"
     34     The new import function
     35
     36     Note that ``name`` is not unique, it can be `sage.foo.bar` or `bar`.
     37     """
     38     global all_modules, import_counter, parent, direct_children_time
     39     old_direct_children_time = direct_children_time
     40     direct_children_time = 0
     41     old_parent = parent
     42     parent = this_import_counter = import_counter
     43     import_counter += 1
    3144     t1 = time.time()
    32      old_parent = parent
    33      parent = name
    34      global_level += 1
    3545     module = old_import(name, globals, locals, fromlist, level)
    36      global_level -= 1
     46     t2 = time.time()
    3747     parent = old_parent
    38      t2 = time.time()
    39      elapsed_times[name] = t2-t1
     48     elapsed_time = t2-t1
     49     module_time = elapsed_time - direct_children_time
     50     direct_children_time = old_direct_children_time + elapsed_time
     51     index_to_parent[this_import_counter] = module
     52     data = all_modules.get(module, None)
     53     if data is not None:
     54          data['parents'].append(parent)
     55          data['import_names'].add(name)
     56          data['cumulative_time'] += elapsed_time
     57          data['time'] += module_time
     58          return module
     59     data = {
     60          'cumulative_time': elapsed_time,
     61          'time': module_time,
     62          'import_names': set([name]),
     63          'parents': [parent] }
     64     all_modules[module] = data
    4065     return module
    4166
    4267old_import = __builtins__.__import__
     68__builtins__.__import__ = new_import
     69gc.disable()
     70from sage.all import *
     71gc.enable()
     72__builtins__.__import__ = old_import
    4373
    44 __builtins__.__import__ = new_import
     74for data in all_modules.values():
     75     data['parents'] = set( index_to_parent.get(i,None) for i in data['parents'] )
    4576
    46 from sage.all import *
     77module_by_speed = sorted([ (data['time'], module, data)
     78                           for module,data in all_modules.iteritems() ])
    4779
    48 parents = {}
    49 for name, level, parent in import_order:
    50      parents[name] = parent
    5180
    52 print "== Tree =="
    53 for name, level,parent in import_order:
    54      try:
    55           print "%s%s: %.3f (%s)" % (" "*level, name, elapsed_times[name], 
    56 parent)
    57      except KeyError:
    58           pass
     81def print_separator():
     82     print '='*72
    5983
    60 print "\n"
    61 print "== Slowest (including children) =="
    62 slowest = sorted((t, name) for (name, t) in elapsed_times.items())[-50:]
    63 for elapsed_time, name in slowest[::-1]:
    64      print "%.3f %s (%s)" % (elapsed_time, name, parents[name])
     84def print_headline(line):
     85     print '=={0:=<68}=='.format(' '+line+' ')
    6586
     87width = 10
     88fmt_header = '{0:>'+str(width)+   '} {1:>'+str(width)+   '} {2:>'+str(width)+'}  {3}'
     89fmt_number = '{0:>'+str(width)+'.3f} {1:>'+str(width)+'.3f} {2:>'+str(width)+'}  {3}'
     90def print_table(module_list, limit):
     91     global fmt_header, fmt_number
     92     print fmt_header.format('exclude/ms', 'include/ms', '#parents', 'module name')
     93     for t, module, data in module_list[-limit:]:
     94          print fmt_number.format(1000*t, 1000*data['cumulative_time'], len(data['parents']), module.__name__)
     95     
    6696
     97if not have_cmdline_args:
     98     print '== Slowest module imports (excluding / including children) =='
     99     print_table(module_by_speed, 50)
     100     print 'Total time (sum over exclusive time): {:.3f}ms'.format(1000*sum(data[0] for data in module_by_speed))
     101     print 'Use sage -startuptime <module_name> to get more details about <module_name>.'
     102else:
     103     for module_arg in cmdline_args:
     104          matching_modules = [m for m in all_modules if m.__name__ == module_arg]
     105          if matching_modules == []:
     106               matching_modules = [m for m in all_modules if m.__name__.endswith(module_arg)]
     107               if len(matching_modules) != 1:
     108                    print matching_modules
     109                    raise ValueError('"'+module_arg+'" does not uniquely determine Sage module.')
     110          module_arg = matching_modules[0]
     111          parents = all_modules[module_arg]['parents']
     112          print
     113          print_separator()
     114          print_headline('Slowest modules importing {0}'.format(module_arg.__name__))
     115          print_table([m for m in module_by_speed if m[1] in parents], 10)
     116          print
     117          print_headline('Slowest modules imported by {0}'.format(module_arg.__name__))
     118          print_table([m for m in module_by_speed if module_arg in m[2]['parents']], 10)
     119          print
     120          data = all_modules[module_arg]
     121          print_headline('module '+module_arg.__name__)
     122          print 'Time to import:  {0:.3f}ms'.format(1000*data['time'])
     123          print 'Cumulative time: {0:.3f}ms'.format(1000*data['cumulative_time'])
     124          print 'Names: {0}'.format(', '.join(data['import_names']))
     125          print 'File: {0}'.format(module_arg.__file__)
    67126