[PATCH 1/2] main: add a --trace option

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

[PATCH 1/2] main: add a --trace option

Mike Frysinger
This helps a lot with debugging as you can quickly get a transcript
of the python code paths that are taken by catalyst.
---
 catalyst/main.py | 49 +++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 49 insertions(+)

diff --git a/catalyst/main.py b/catalyst/main.py
index f48293e..3550809 100644
--- a/catalyst/main.py
+++ b/catalyst/main.py
@@ -170,6 +170,11 @@ $ catalyst -f stage1-specfile.spec"""
  dest='color', action='store_false',
  help='never colorize output all the time (default: detect)')
 
+ group = parser.add_argument_group('Developer options')
+ group.add_argument('--trace',
+ default=False, action='store_true',
+ help='trace program output (akin to `sh -x`)')
+
  group = parser.add_argument_group('Temporary file management')
  group.add_argument('-a', '--clear-autoresume',
  default=False, action='store_true',
@@ -203,10 +208,54 @@ $ catalyst -f stage1-specfile.spec"""
  return parser
 
 
+def trace(func, *args, **kwargs):
+ """Run |func| through the trace module (akin to `sh -x`)"""
+ import trace
+
+ # Ignore common system modules we use.
+ ignoremods = set((
+ 'argparse',
+ 'genericpath', 'gettext',
+ 'locale',
+ 'os',
+ 'posixpath',
+ 're',
+ 'sre_compile', 'sre_parse', 'sys',
+ 'tempfile', 'threading',
+ 'UserDict',
+ ))
+
+ # Ignore all the system modules.
+ ignoredirs = set(sys.path)
+ # But try to strip out the catalyst paths.
+ try:
+ ignoredirs.remove(os.path.dirname(os.path.dirname(
+ os.path.realpath(__file__))))
+ except KeyError:
+ pass
+
+ tracer = trace.Trace(
+ count=False,
+ trace=True,
+ timing=True,
+ ignoremods=ignoremods,
+ ignoredirs=ignoredirs)
+ return tracer.runfunc(func, *args, **kwargs)
+
+
 def main(argv):
+ """The main entry point for frontends to use"""
  parser = get_parser()
  opts = parser.parse_args(argv)
 
+ if opts.trace:
+ return trace(_main, parser, opts)
+ else:
+ return _main(parser, opts)
+
+
+def _main(parser, opts):
+ """The "main" main function so we can trace/profile."""
  # Initialize the logger before anything else.
  log_level = opts.log_level
  if log_level is None:
--
2.6.2


Reply | Threaded
Open this post in threaded view
|

[PATCH 2/2] main: add a --profile option

Mike Frysinger
When things get slow, this option helps narrow down where things
are getting hung up.
---
 catalyst/main.py | 24 ++++++++++++++++++++++++
 1 file changed, 24 insertions(+)

diff --git a/catalyst/main.py b/catalyst/main.py
index 3550809..cb90e66 100644
--- a/catalyst/main.py
+++ b/catalyst/main.py
@@ -174,6 +174,9 @@ $ catalyst -f stage1-specfile.spec"""
  group.add_argument('--trace',
  default=False, action='store_true',
  help='trace program output (akin to `sh -x`)')
+ group.add_argument('--profile',
+ default=False, action='store_true',
+ help='profile program execution')
 
  group = parser.add_argument_group('Temporary file management')
  group.add_argument('-a', '--clear-autoresume',
@@ -243,6 +246,25 @@ def trace(func, *args, **kwargs):
  return tracer.runfunc(func, *args, **kwargs)
 
 
+def profile(func, *args, **kwargs):
+ """Run |func| through the profile module"""
+ # Should make this an option.
+ sort_keys = ('time',)
+
+ # Collect the profile.
+ import cProfile
+ profiler = cProfile.Profile(subcalls=True, builtins=True)
+ try:
+ ret = profiler.runcall(func, *args, **kwargs)
+ finally:
+ # Then process the results.
+ import pstats
+ stats = pstats.Stats(profiler, stream=sys.stderr)
+ stats.strip_dirs().sort_stats(*sort_keys).print_stats()
+
+ return ret
+
+
 def main(argv):
  """The main entry point for frontends to use"""
  parser = get_parser()
@@ -250,6 +272,8 @@ def main(argv):
 
  if opts.trace:
  return trace(_main, parser, opts)
+ elif opts.profile:
+ return profile(_main, parser, opts)
  else:
  return _main(parser, opts)
 
--
2.6.2


Reply | Threaded
Open this post in threaded view
|

Re: [PATCH 1/2] main: add a --trace option

Mike Frysinger
In reply to this post by Mike Frysinger
On 23 Nov 2015 07:07, Mike Frysinger wrote:
> This helps a lot with debugging as you can quickly get a transcript
> of the python code paths that are taken by catalyst.

example output:
$ ./bin/catalyst.git --trace
 --- modulename: main, funcname: _main
0.00 main.py(284): log_level = opts.log_level
0.00 main.py(285): if log_level is None:
0.00 main.py(286): if opts.debug:
0.00 main.py(288): elif opts.verbose:
0.00 main.py(291): log_level = 'notice'
0.00 main.py(292): log.setup_logging(log_level, output=opts.log_file, debug=opts.debug,
0.00 main.py(293): color=opts.color)
 --- modulename: log, funcname: setup_logging
0.00 log.py(109): level = logging.getLevelName(level.upper())
0.00 log.py(112): fmt = '%(asctime)s: %(levelname)-8s: '
0.00 log.py(113): if debug:
0.00 log.py(115): fmt += '%(message)s'
0.00 log.py(118): if output is None:
0.00 log.py(119): handler = logging.StreamHandler(stream=sys.stdout)
0.00 log.py(125): tzname = time.strftime('%Z', time.localtime())
0.00 log.py(126): datefmt = '%d %b %Y %H:%M:%S ' + tzname
0.00 log.py(127): formatter = CatalystFormatter(fmt, datefmt, color=color)
 --- modulename: log, funcname: __init__
0.00 log.py(83): color = kwargs.pop('color', None)
0.00 log.py(84): if color is None:
0.00 log.py(85): color = self.detect_color()
 --- modulename: log, funcname: detect_color
0.00 log.py(77): if 'NOCOLOR' is os.environ:
0.00 log.py(79): return os.isatty(sys.stdout.fileno())
0.00 log.py(86): if not color:
0.00 log.py(87): self._COLORS = {}
0.00 log.py(89): super(CatalystFormatter, self).__init__(*args, **kwargs)
0.00 log.py(128): handler.setFormatter(formatter)
0.00 log.py(130): logger.addHandler(handler)
0.00 log.py(131): logger.setLevel(level)
0.00 main.py(296): myconfigs = opts.configs
0.00 main.py(297): if not myconfigs:
0.00 main.py(299): myspecfile = opts.file
0.00 main.py(300): mycmdline = opts.cli[:]
0.00 main.py(302): if opts.snapshot:
0.00 main.py(306): conf_values['DEBUG'] = opts.debug
0.00 main.py(307): conf_values['VERBOSE'] = opts.debug or opts.verbose
0.00 main.py(309): options = set()
0.00 main.py(310): if opts.fetchonly:
0.00 main.py(312): if opts.purge:
0.00 main.py(314): if opts.purgeonly:
0.00 main.py(316): if opts.purgetmponly:
0.00 main.py(318): if opts.clear_autoresume:
0.00 main.py(322): if not myspecfile and not mycmdline:
0.00 main.py(323): parser.error('please specify one of either -f or -C or -s')
usage: catalyst [-h] [-V] [-d] [-v]
                [--log-level {critical,error,warning,notice,info,debug}]
                [--log-file LOG_FILE] [--color] [--nocolor] [--trace]
                [--profile] [-a] [-p] [-P] [-T] [-F] [-c CONFIGS] [-f FILE]
                [-s SNAPSHOT] [-C ...]
catalyst: error: please specify one of either -f or -C or -s

signature.asc (836 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: [PATCH 2/2] main: add a --profile option

Mike Frysinger
In reply to this post by Mike Frysinger
On 23 Nov 2015 07:07, Mike Frysinger wrote:
> When things get slow, this option helps narrow down where things
> are getting hung up.

example output (although not as interesting since it's not a full run):
$ ./bin/catalyst.git --profile
usage: catalyst [-h] [-V] [-d] [-v]
                [--log-level {critical,error,warning,notice,info,debug}]
                [--log-file LOG_FILE] [--color] [--nocolor] [--trace]
                [--profile] [-a] [-p] [-P] [-T] [-F] [-c CONFIGS] [-f FILE]
                [-s SNAPSHOT] [-C ...]
catalyst: error: please specify one of either -f or -C or -s

         2133 function calls (2090 primitive calls) in 0.002 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        6    0.000    0.000    0.001    0.000 argparse.py:384(_format_actions_usage)
     10/7    0.000    0.000    0.000    0.000 sre_parse.py:395(_parse)
        4    0.000    0.000    0.000    0.000 argparse.py:336(get_lines)
       25    0.000    0.000    0.000    0.000 {method 'sub' of '_sre.SRE_Pattern' objects}
     18/5    0.000    0.000    0.000    0.000 sre_compile.py:64(_compile)
       30    0.000    0.000    0.001    0.000 re.py:230(_compile)
        3    0.000    0.000    0.000    0.000 gettext.py:424(find)
       73    0.000    0.000    0.000    0.000 sre_parse.py:193(__next)
    25/12    0.000    0.000    0.000    0.000 sre_parse.py:151(getwidth)
        2    0.000    0.000    0.002    0.001 argparse.py:292(_format_usage)
        6    0.000    0.000    0.000    0.000 gettext.py:132(_expand_lang)
      430    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        5    0.000    0.000    0.000    0.000 sre_compile.py:433(_compile_info)
       67    0.000    0.000    0.000    0.000 sre_parse.py:141(__getitem__)
       12    0.000    0.000    0.000    0.000 posixpath.py:61(join)
  399/388    0.000    0.000    0.000    0.000 {len}
      113    0.000    0.000    0.000    0.000 {isinstance}
        6    0.000    0.000    0.000    0.000 sre_compile.py:256(_optimize_charset)
       24    0.000    0.000    0.000    0.000 argparse.py:573(_format_args)
       12    0.000    0.000    0.000    0.000 {posix.stat}
       57    0.000    0.000    0.000    0.000 sre_parse.py:212(get)
       12    0.000    0.000    0.000    0.000 genericpath.py:23(exists)
       24    0.000    0.000    0.000    0.000 argparse.py:557(_metavar_formatter)
      8/5    0.000    0.000    0.000    0.000 sre_parse.py:317(_parse_sub)
       61    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        4    0.000    0.000    0.000    0.000 {method 'findall' of '_sre.SRE_Pattern' objects}
        3    0.000    0.000    0.000    0.000 sre_parse.py:734(parse_template)
        5    0.000    0.000    0.000    0.000 sre_parse.py:706(parse)
       24    0.000    0.000    0.001    0.000 re.py:148(sub)
        5    0.000    0.000    0.001    0.000 sre_compile.py:567(compile)
       18    0.000    0.000    0.000    0.000 re.py:264(_compile_repl)
        6    0.000    0.000    0.000    0.000 sre_compile.py:228(_compile_charset)
        2    0.000    0.000    0.000    0.000 {method 'write' of 'file' objects}
        1    0.000    0.000    0.000    0.000 log.py:105(setup_logging)
       38    0.000    0.000    0.000    0.000 sre_parse.py:137(__len__)
        6    0.000    0.000    0.000    0.000 locale.py:363(normalize)
        6    0.000    0.000    0.000    0.000 {sorted}
        5    0.000    0.000    0.000    0.000 sre_compile.py:552(_code)
        1    0.000    0.000    0.000    0.000 argparse.py:154(__init__)
       20    0.000    0.000    0.000    0.000 argparse.py:566(format)
       40    0.000    0.000    0.000    0.000 sre_parse.py:206(match)
       18    0.000    0.000    0.000    0.000 sre_parse.py:92(__init__)
       18    0.000    0.000    0.000    0.000 re.py:284(_subx)
        1    0.000    0.000    0.002    0.002 argparse.py:205(format_help)
       40    0.000    0.000    0.000    0.000 {min}
        7    0.000    0.000    0.000    0.000 sre_compile.py:428(_simple)
        1    0.000    0.000    0.002    0.002 main.py:281(_main)
        1    0.000    0.000    0.000    0.000 {time.localtime}
       29    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        3    0.000    0.000    0.000    0.000 gettext.py:530(dgettext)
       12    0.000    0.000    0.000    0.000 UserDict.py:58(get)
       26    0.000    0.000    0.000    0.000 {method 'find' of 'bytearray' objects}
        3    0.000    0.000    0.000    0.000 locale.py:347(_replace_encoding)
        3    0.000    0.000    0.000    0.000 gettext.py:464(translation)
        7    0.000    0.000    0.000    0.000 sre_parse.py:268(_escape)
        4    0.000    0.000    0.000    0.000 re.py:173(findall)
       25    0.000    0.000    0.000    0.000 {method 'upper' of 'str' objects}
       10    0.000    0.000    0.000    0.000 sre_compile.py:546(isstring)
        4    0.000    0.000    0.000    0.000 sre_parse.py:236(_class_escape)
        1    0.000    0.000    0.000    0.000 {time.strftime}
       21    0.000    0.000    0.000    0.000 sre_parse.py:149(append)
        1    0.000    0.000    0.000    0.000 __init__.py:644(_addHandlerRef)
       18    0.000    0.000    0.000    0.000 {method 'find' of 'str' objects}
        3    0.000    0.000    0.000    0.000 __init__.py:49(normalize_encoding)
        9    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        5    0.000    0.000    0.000    0.000 {_sre.compile}
        2    0.000    0.000    0.000    0.000 threading.py:147(acquire)
        8    0.000    0.000    0.000    0.000 sre_parse.py:189(__init__)
       36    0.000    0.000    0.000    0.000 {method 'endswith' of 'str' objects}
       36    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}
        3    0.000    0.000    0.000    0.000 sre_parse.py:85(closegroup)
        1    0.000    0.000    0.000    0.000 log.py:81(__init__)
        3    0.000    0.000    0.000    0.000 gettext.py:568(gettext)
        1    0.000    0.000    0.000    0.000 __init__.py:154(getLevelName)
        1    0.000    0.000    0.000    0.000 __init__.py:825(__init__)
        9    0.000    0.000    0.000    0.000 {method 'translate' of 'str' objects}
       12    0.000    0.000    0.000    0.000 UserDict.py:70(__contains__)
        1    0.000    0.000    0.002    0.002 argparse.py:2364(error)
        2    0.000    0.000    0.000    0.000 __init__.py:183(_checkLevel)
        1    0.000    0.000    0.000    0.000 argparse.py:250(add_usage)
        1    0.000    0.000    0.000    0.000 log.py:74(detect_color)
        5    0.000    0.000    0.000    0.000 sre_parse.py:67(__init__)
        1    0.000    0.000    0.000    0.000 threading.py:132(__init__)
        7    0.000    0.000    0.000    0.000 {method 'strip' of 'str' objects}
        1    0.000    0.000    0.000    0.000 argparse.py:2326(_get_formatter)
        4    0.000    0.000    0.000    0.000 UserDict.py:18(__getitem__)
        2    0.000    0.000    0.000    0.000 argparse.py:2350(_print_message)
        1    0.000    0.000    0.000    0.000 __init__.py:663(__init__)
        1    0.000    0.000    0.002    0.002 argparse.py:2332(print_usage)
        4    0.000    0.000    0.000    0.000 {hasattr}
        1    0.000    0.000    0.000    0.000 __init__.py:692(createLock)
        2    0.000    0.000    0.000    0.000 threading.py:187(release)
        2    0.000    0.000    0.000    0.000 re.py:192(compile)
        1    0.000    0.000    0.002    0.002 argparse.py:2287(format_usage)
        3    0.000    0.000    0.000    0.000 sre_parse.py:74(opengroup)
        2    0.000    0.000    0.000    0.000 argparse.py:287(_join_parts)
        6    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
       18    0.000    0.000    0.000    0.000 {ord}
        1    0.000    0.000    0.002    0.002 argparse.py:280(format_help)
        3    0.000    0.000    0.000    0.000 {method 'index' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'acquire' of 'thread.lock' objects}
        1    0.000    0.000    0.000    0.000 {posix.isatty}
        6    0.000    0.000    0.000    0.000 {method 'reverse' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'fileno' of 'file' objects}
        1    0.000    0.000    0.000    0.000 argparse.py:199(__init__)
        6    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
        1    0.000    0.000    0.000    0.000 threading.py:114(RLock)
        2    0.000    0.000    0.000    0.000 __init__.py:220(_releaseLock)
        4    0.000    0.000    0.000    0.000 {max}
        1    0.000    0.000    0.000    0.000 __init__.py:585(__init__)
        7    0.000    0.000    0.000    0.000 sre_parse.py:145(__setitem__)
        1    0.000    0.000    0.000    0.000 __init__.py:1137(setLevel)
        1    0.000    0.000    0.000    0.000 argparse.py:2359(exit)
        1    0.000    0.000    0.000    0.000 {sys.exit}
        1    0.000    0.000    0.000    0.000 __init__.py:397(__init__)
        2    0.000    0.000    0.000    0.000 {method 'release' of 'thread.lock' objects}
        1    0.000    0.000    0.000    0.000 __init__.py:762(setFormatter)
        2    0.000    0.000    0.000    0.000 __init__.py:211(_acquireLock)
        1    0.000    0.000    0.000    0.000 __init__.py:1296(addHandler)
        6    0.000    0.000    0.000    0.000 {range}
        1    0.000    0.000    0.000    0.000 {method 'pop' of 'dict' objects}
        4    0.000    0.000    0.000    0.000 {thread.get_ident}
        5    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 argparse.py:230(_add_item)
        1    0.000    0.000    0.000    0.000 {thread.allocate_lock}
        3    0.000    0.000    0.000    0.000 {method 'remove' of 'list' objects}
        1    0.000    0.000    0.000    0.000 threading.py:80(__init__)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
-mike

signature.asc (836 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: [PATCH 1/2] main: add a --trace option

Brian Dolbec-3
In reply to this post by Mike Frysinger
On Mon, 23 Nov 2015 07:07:40 -0500
Mike Frysinger <[hidden email]> wrote:

> This helps a lot with debugging as you can quickly get a transcript
> of the python code paths that are taken by catalyst.
> ---
>  catalyst/main.py | 49
> +++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 49
> insertions(+)
>
> diff --git a/catalyst/main.py b/catalyst/main.py
> index f48293e..3550809 100644
> --- a/catalyst/main.py
> +++ b/catalyst/main.py
> @@ -170,6 +170,11 @@ $ catalyst -f stage1-specfile.spec"""
>   dest='color', action='store_false',
>   help='never colorize output all the time (default:
> detect)')
> + group = parser.add_argument_group('Developer options')
> + group.add_argument('--trace',
> + default=False, action='store_true',
> + help='trace program output (akin to `sh -x`)')
> +
>   group = parser.add_argument_group('Temporary file
> management') group.add_argument('-a', '--clear-autoresume',
>   default=False, action='store_true',
> @@ -203,10 +208,54 @@ $ catalyst -f stage1-specfile.spec"""
>   return parser
>  
>  
> +def trace(func, *args, **kwargs):
> + """Run |func| through the trace module (akin to `sh -x`)"""
> + import trace
> +
> + # Ignore common system modules we use.
> + ignoremods = set((
> + 'argparse',
> + 'genericpath', 'gettext',
> + 'locale',
> + 'os',
> + 'posixpath',
> + 're',
> + 'sre_compile', 'sre_parse', 'sys',
> + 'tempfile', 'threading',
> + 'UserDict',
> + ))
> +
> + # Ignore all the system modules.
> + ignoredirs = set(sys.path)
> + # But try to strip out the catalyst paths.
> + try:
> + ignoredirs.remove(os.path.dirname(os.path.dirname(
> + os.path.realpath(__file__))))
> + except KeyError:
> + pass
> +
> + tracer = trace.Trace(
> + count=False,
> + trace=True,
> + timing=True,
> + ignoremods=ignoremods,
> + ignoredirs=ignoredirs)
> + return tracer.runfunc(func, *args, **kwargs)
> +
> +
>  def main(argv):
> + """The main entry point for frontends to use"""
>   parser = get_parser()
>   opts = parser.parse_args(argv)
>  
> + if opts.trace:
> + return trace(_main, parser, opts)
> + else:
> + return _main(parser, opts)
> +
> +
> +def _main(parser, opts):
> + """The "main" main function so we can trace/profile."""
>   # Initialize the logger before anything else.
>   log_level = opts.log_level
>   if log_level is None:


Yeah, looks good.  Not sure I'll use it yet, but...
--
Brian Dolbec <dolsen>


Reply | Threaded
Open this post in threaded view
|

Re: [PATCH 2/2] main: add a --profile option

Brian Dolbec-3
In reply to this post by Mike Frysinger
On Mon, 23 Nov 2015 07:07:41 -0500
Mike Frysinger <[hidden email]> wrote:

> When things get slow, this option helps narrow down where things
> are getting hung up.
> ---
>  catalyst/main.py | 24 ++++++++++++++++++++++++
>  1 file changed, 24 insertions(+)
>
> diff --git a/catalyst/main.py b/catalyst/main.py
> index 3550809..cb90e66 100644
> --- a/catalyst/main.py
> +++ b/catalyst/main.py
> @@ -174,6 +174,9 @@ $ catalyst -f stage1-specfile.spec"""
>   group.add_argument('--trace',
>   default=False, action='store_true',
>   help='trace program output (akin to `sh -x`)')
> + group.add_argument('--profile',
> + default=False, action='store_true',
> + help='profile program execution')
>  
>   group = parser.add_argument_group('Temporary file
> management') group.add_argument('-a', '--clear-autoresume',
> @@ -243,6 +246,25 @@ def trace(func, *args, **kwargs):
>   return tracer.runfunc(func, *args, **kwargs)
>  
>  
> +def profile(func, *args, **kwargs):
> + """Run |func| through the profile module"""
> + # Should make this an option.
> + sort_keys = ('time',)
> +
> + # Collect the profile.
> + import cProfile
> + profiler = cProfile.Profile(subcalls=True, builtins=True)
> + try:
> + ret = profiler.runcall(func, *args, **kwargs)
> + finally:
> + # Then process the results.
> + import pstats
> + stats = pstats.Stats(profiler, stream=sys.stderr)
> +
> stats.strip_dirs().sort_stats(*sort_keys).print_stats() +
> + return ret
> +
> +
>  def main(argv):
>   """The main entry point for frontends to use"""
>   parser = get_parser()
> @@ -250,6 +272,8 @@ def main(argv):
>  
>   if opts.trace:
>   return trace(_main, parser, opts)
> + elif opts.profile:
> + return profile(_main, parser, opts)
>   else:
>   return _main(parser, opts)
>  

Profiling is good :)


--
Brian Dolbec <dolsen>