From 4c441c75b1d5d0430d7bd1298552d653cce6cadc Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Mon, 15 May 2017 20:06:13 +0200 Subject: Implement --debug-profile --- src/borg/archiver.py | 19 ++++++++++++++++++- src/borg/testsuite/archiver.py | 10 ++++++++++ 2 files changed, 28 insertions(+), 1 deletion(-) diff --git a/src/borg/archiver.py b/src/borg/archiver.py index ecde3f7d6..e5c606d15 100644 --- a/src/borg/archiver.py +++ b/src/borg/archiver.py @@ -2049,6 +2049,8 @@ class Archiver: add_common_option('--consider-part-files', dest='consider_part_files', action='store_true', default=False, help='treat part files like normal files (e.g. to list/extract them)') + add_common_option('--debug-profile', dest='debug_profile', default=None, metavar='FILE', + help='Store a Python profile at FILE') parser = argparse.ArgumentParser(prog=self.prog, description='Borg - Deduplicated Backups', add_help=False) @@ -3542,7 +3544,22 @@ class Archiver: self.prerun_checks(logger) if is_slow_msgpack(): logger.warning("Using a pure-python msgpack! This will result in lower performance.") - return set_ec(func(args)) + if args.debug_profile: + # Import these only when needed - avoids a further increase in startup time + import cProfile + import marshal + logger.debug('Writing execution profile to %s', args.debug_profile) + # Open the file early, before running the main program, to avoid + # a very late crash in case the specified path is invalid + with open(args.debug_profile, 'wb') as fd: + profiler = cProfile.Profile() + variables = dict(locals()) + profiler.runctx('rc = set_ec(func(args))', globals(), variables) + profiler.snapshot_stats() + marshal.dump(profiler.stats, fd) + return variables['rc'] + else: + return set_ec(func(args)) def sig_info_handler(sig_no, stack): # pragma: no cover diff --git a/src/borg/testsuite/archiver.py b/src/borg/testsuite/archiver.py index 842b8f0a2..e2c2be5c7 100644 --- a/src/borg/testsuite/archiver.py +++ b/src/borg/testsuite/archiver.py @@ -3,6 +3,7 @@ import errno import json import logging import os +import pstats import random import shutil import socket @@ -1681,6 +1682,15 @@ class ArchiverTestCase(ArchiverTestCaseBase): assert log_message['name'].startswith('borg.') assert isinstance(log_message['message'], str) + def test_debug_profile(self): + self.create_test_files() + self.cmd('init', '--encryption=repokey', self.repository_location) + self.cmd('create', self.repository_location + '::test', 'input', '--debug-profile=create.prof') + stats = pstats.Stats('create.prof') + stats.strip_dirs() + stats.sort_stats('cumtime') + # Ok, stats can be loaded, good enough. + def test_common_options(self): self.create_test_files() self.cmd('init', '--encryption=repokey', self.repository_location) -- cgit v1.2.3 From a07463c96a642ff923019f0a328e165a4c6da63a Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Mon, 15 May 2017 23:26:44 +0200 Subject: --debug-profile: use msgpack instead of marshal by default --- scripts/msgpack2marshal.py | 18 ++++++++++++++++++ src/borg/archiver.py | 27 +++++++++++++++++++++------ src/borg/testsuite/archiver.py | 10 ++++++++-- 3 files changed, 47 insertions(+), 8 deletions(-) create mode 100755 scripts/msgpack2marshal.py diff --git a/scripts/msgpack2marshal.py b/scripts/msgpack2marshal.py new file mode 100755 index 000000000..890da1ddb --- /dev/null +++ b/scripts/msgpack2marshal.py @@ -0,0 +1,18 @@ +#!/usr/bin/env python3 +import marshal +import sys + +import msgpack + +if len(sys.argv) not in (2, 3): + print('Synopsis:', sys.argv[0], '', '[marshal output]', file=sys.stderr) + sys.exit(1) + +if len(sys.argv) == 2: + outfile = sys.stdout +else: + outfile = open(sys.argv[2], 'wb') + +with outfile: + with open(sys.argv[1], 'rb') as infile: + marshal.dump(msgpack.unpack(infile, use_list=False, encoding='utf-8'), outfile) diff --git a/src/borg/archiver.py b/src/borg/archiver.py index e5c606d15..87bc1e255 100644 --- a/src/borg/archiver.py +++ b/src/borg/archiver.py @@ -2050,7 +2050,8 @@ class Archiver: action='store_true', default=False, help='treat part files like normal files (e.g. to list/extract them)') add_common_option('--debug-profile', dest='debug_profile', default=None, metavar='FILE', - help='Store a Python profile at FILE') + help='Write Python profile in msgpack format into FILE. For local use a cProfile-' + 'compatible file can be generated by suffixing FILE with ".pyprof".') parser = argparse.ArgumentParser(prog=self.prog, description='Borg - Deduplicated Backups', add_help=False) @@ -3545,7 +3546,7 @@ class Archiver: if is_slow_msgpack(): logger.warning("Using a pure-python msgpack! This will result in lower performance.") if args.debug_profile: - # Import these only when needed - avoids a further increase in startup time + # Import only when needed - avoids a further increase in startup time import cProfile import marshal logger.debug('Writing execution profile to %s', args.debug_profile) @@ -3554,10 +3555,24 @@ class Archiver: with open(args.debug_profile, 'wb') as fd: profiler = cProfile.Profile() variables = dict(locals()) - profiler.runctx('rc = set_ec(func(args))', globals(), variables) - profiler.snapshot_stats() - marshal.dump(profiler.stats, fd) - return variables['rc'] + profiler.enable() + try: + return set_ec(func(args)) + finally: + profiler.disable() + profiler.snapshot_stats() + if args.debug_profile.endswith('.pyprof'): + marshal.dump(profiler.stats, fd) + else: + # We use msgpack here instead of the marshal module used by cProfile itself, + # because the latter is insecure. Since these files may be shared over the + # internet we don't want a format that is impossible to interpret outside + # an insecure implementation. + # See scripts/msgpack2marshal.py for a small script that turns a msgpack file + # into a marshal file that can be read by e.g. pyprof2calltree. + # For local use it's unnecessary hassle, though, that's why .pyprof makes + # it compatible (see above). + msgpack.pack(profiler.stats, fd, use_bin_type=True) else: return set_ec(func(args)) diff --git a/src/borg/testsuite/archiver.py b/src/borg/testsuite/archiver.py index e2c2be5c7..a3e224285 100644 --- a/src/borg/testsuite/archiver.py +++ b/src/borg/testsuite/archiver.py @@ -1686,10 +1686,16 @@ class ArchiverTestCase(ArchiverTestCaseBase): self.create_test_files() self.cmd('init', '--encryption=repokey', self.repository_location) self.cmd('create', self.repository_location + '::test', 'input', '--debug-profile=create.prof') - stats = pstats.Stats('create.prof') + stats = pstats.Stats() + with open('create.prof', 'rb') as fd: + stats.stats = msgpack.unpack(fd, use_list=False, encoding='utf-8') + stats.strip_dirs() + stats.sort_stats('cumtime') + + self.cmd('create', self.repository_location + '::test2', 'input', '--debug-profile=create.pyprof') + stats = pstats.Stats('create.pyprof') # Only do this on trusted data! stats.strip_dirs() stats.sort_stats('cumtime') - # Ok, stats can be loaded, good enough. def test_common_options(self): self.create_test_files() -- cgit v1.2.3 From 6d6ae65be3b88682bd86aaa900d9114859968104 Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Tue, 16 May 2017 23:13:31 +0200 Subject: replace external script with "borg debug convert-profile" --- scripts/msgpack2marshal.py | 18 ------------------ src/borg/archiver.py | 25 +++++++++++++++++++++++-- src/borg/testsuite/archiver.py | 5 ++--- 3 files changed, 25 insertions(+), 23 deletions(-) delete mode 100755 scripts/msgpack2marshal.py diff --git a/scripts/msgpack2marshal.py b/scripts/msgpack2marshal.py deleted file mode 100755 index 890da1ddb..000000000 --- a/scripts/msgpack2marshal.py +++ /dev/null @@ -1,18 +0,0 @@ -#!/usr/bin/env python3 -import marshal -import sys - -import msgpack - -if len(sys.argv) not in (2, 3): - print('Synopsis:', sys.argv[0], '', '[marshal output]', file=sys.stderr) - sys.exit(1) - -if len(sys.argv) == 2: - outfile = sys.stdout -else: - outfile = open(sys.argv[2], 'wb') - -with outfile: - with open(sys.argv[1], 'rb') as infile: - marshal.dump(msgpack.unpack(infile, use_list=False, encoding='utf-8'), outfile) diff --git a/src/borg/archiver.py b/src/borg/archiver.py index 87bc1e255..cfb4ff393 100644 --- a/src/borg/archiver.py +++ b/src/borg/archiver.py @@ -1576,6 +1576,13 @@ class Archiver: print("object %s not found [info from chunks cache]." % hex_id) return EXIT_SUCCESS + def do_debug_convert_profile(self, args): + """convert Borg profile to Python profile""" + import marshal + with args.output, args.input: + marshal.dump(msgpack.unpack(args.input, use_list=False, encoding='utf-8'), args.output) + return EXIT_SUCCESS + @with_repository(lock=False, manifest=False) def do_break_lock(self, args, repository): """Break the repository lock (e.g. in case it was left by a dead borg.""" @@ -2050,7 +2057,7 @@ class Archiver: action='store_true', default=False, help='treat part files like normal files (e.g. to list/extract them)') add_common_option('--debug-profile', dest='debug_profile', default=None, metavar='FILE', - help='Write Python profile in msgpack format into FILE. For local use a cProfile-' + help='Write execution profile in Borg format into FILE. For local use a Python-' 'compatible file can be generated by suffixing FILE with ".pyprof".') parser = argparse.ArgumentParser(prog=self.prog, description='Borg - Deduplicated Backups', @@ -3390,6 +3397,20 @@ class Archiver: subparser.add_argument('ids', metavar='IDs', nargs='+', type=str, help='hex object ID(s) to show refcounts for') + debug_convert_profile_epilog = process_epilog(""" + Convert a Borg profile to a Python cProfile compatible profile. + """) + subparser = debug_parsers.add_parser('convert-profile', parents=[common_parser], add_help=False, + description=self.do_debug_convert_profile.__doc__, + epilog=debug_convert_profile_epilog, + formatter_class=argparse.RawDescriptionHelpFormatter, + help='convert Borg profile to Python profile (debug)') + subparser.set_defaults(func=self.do_debug_convert_profile) + subparser.add_argument('input', metavar='INPUT', type=argparse.FileType('rb'), + help='Borg profile') + subparser.add_argument('output', metavar='OUTPUT', type=argparse.FileType('wb'), + help='Output file') + benchmark_epilog = process_epilog("These commands do various benchmarks.") subparser = subparsers.add_parser('benchmark', parents=[mid_common_parser], add_help=False, @@ -3551,7 +3572,7 @@ class Archiver: import marshal logger.debug('Writing execution profile to %s', args.debug_profile) # Open the file early, before running the main program, to avoid - # a very late crash in case the specified path is invalid + # a very late crash in case the specified path is invalid. with open(args.debug_profile, 'wb') as fd: profiler = cProfile.Profile() variables = dict(locals()) diff --git a/src/borg/testsuite/archiver.py b/src/borg/testsuite/archiver.py index a3e224285..d41d3b7b2 100644 --- a/src/borg/testsuite/archiver.py +++ b/src/borg/testsuite/archiver.py @@ -1686,9 +1686,8 @@ class ArchiverTestCase(ArchiverTestCaseBase): self.create_test_files() self.cmd('init', '--encryption=repokey', self.repository_location) self.cmd('create', self.repository_location + '::test', 'input', '--debug-profile=create.prof') - stats = pstats.Stats() - with open('create.prof', 'rb') as fd: - stats.stats = msgpack.unpack(fd, use_list=False, encoding='utf-8') + self.cmd('debug', 'convert-profile', 'create.prof', 'create.pyprof') + stats = pstats.Stats('create.pyprof') stats.strip_dirs() stats.sort_stats('cumtime') -- cgit v1.2.3 From 054897c8724e1933d1ed3a1ec537046f30968e18 Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Tue, 16 May 2017 23:18:48 +0200 Subject: docs: debugging facilities --- docs/usage.rst | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) diff --git a/docs/usage.rst b/docs/usage.rst index d2b0904a6..bde9a9955 100644 --- a/docs/usage.rst +++ b/docs/usage.rst @@ -505,8 +505,8 @@ Miscellaneous Help .. include:: usage/help.rst.inc -Debug Commands --------------- +Debugging Facilities +-------------------- There is a ``borg debug`` command that has some subcommands which are all **not intended for normal use** and **potentially very dangerous** if used incorrectly. @@ -525,6 +525,20 @@ They exist to improve debugging capabilities without direct system access, e.g. in case you ever run into some severe malfunction. Use them only if you know what you are doing or if a trusted |project_name| developer tells you what to do. +Borg has a ``--debug-topic TOPIC`` option to enable specific debugging messages. Topics +are generally not documented. + +A ``--debug-profile FILE`` option exists which writes a profile of the main program's +execution to a file. The format of these files is not directly compatible with the +Python profiling tools, since these use the "marshal" format, which is not intended +to be secure (quoting the Python docs: "Never unmarshal data received from an untrusted +or unauthenticated source."). + +The ``borg debug profile-convert`` command can be used to take a Borg profile and convert +it to a profile file that is compatible with the Python tools. + +Additionally, if the filename specified for ``--debug-profile`` ends with ".pyprof" a +Python compatible profile is generated. This is only intended for local use by developers. Additional Notes ---------------- -- cgit v1.2.3