Merge pull request #2653 from inkstitch/kgn/debug_profile_extend_vscode

Kgn/debug profile extend vscode

2 files changed, 371 insertions, 39 deletions

diff --git a/lib/debug.py b/lib/debug.py
index 4751e6af..eb49005a 100644
--- a/lib/debug.py
+++ b/lib/debug.py
@@ -3,21 +3,25 @@
 # Copyright (c) 2010 Authors
 # Licensed under the GNU GPL version 3.0 or later.  See the file LICENSE for details.
 
-import atexit
 import os
-import socket
 import sys
-import time
-from contextlib import contextmanager
-from datetime import datetime
+import atexit  # to save svg file on exit
+import socket  # to check if debugger is running
+import time    # to measure time of code block, use time.monotonic() instead of time.time()
+from datetime import datetime  
+
+from contextlib import contextmanager  # to measure time of with block
+import configparser  # to read DEBUG.ini
+from pathlib import Path # to work with paths as objects
 
 import inkex
-from lxml import etree
+from lxml import etree   # to create svg file
 
 from .svg import line_strings_to_path
 from .svg.tags import INKSCAPE_GROUPMODE, INKSCAPE_LABEL
 
-
+# decorator to check if debugging is enabled
+# - if debug is not enabled then decorated function is not called
 def check_enabled(func):
     def decorated(self, *args, **kwargs):
         if self.enabled:
@@ -26,13 +30,17 @@ def check_enabled(func):
     return decorated
 
 
+# unwrapping = provision for functions as arguments
+# - if argument is callable then it is called and return value is used as argument
+#   otherwise argument is returned as is
 def _unwrap(arg):
     if callable(arg):
         return arg()
     else:
         return arg
 
-
+# decorator to unwrap arguments if they are callable
+#   eg: if argument is lambda function then it is called and return value is used as argument
 def unwrap_arguments(func):
     def decorated(self, *args, **kwargs):
         unwrapped_args = [_unwrap(arg) for arg in args]
@@ -62,36 +70,85 @@ class Debug(object):
     """
 
     def __init__(self):
+        self.debugger = None
+        self.wait_attach = True
         self.enabled = False
         self.last_log_time = None
         self.current_layer = None
         self.group_stack = []
 
-    def enable(self):
+    def enable(self, debug_type, debug_dir : Path, ini : configparser.ConfigParser):
+        # initilize file names and other parameters from DEBUG.ini file
+        self.debug_dir = debug_dir  # directory where debug files are stored
+        self.debug_log_file = ini.get("DEBUG","debug_log_file", fallback="debug.log")
+        self.debug_svg_file = ini.get("DEBUG","debug_svg_file", fallback="debug.svg")
+        self.wait_attach = ini.getboolean("DEBUG","wait_attach", fallback=True) # currently only for vscode
+
+        if debug_type == 'none':
+            return
+        
+        self.debugger = debug_type
         self.enabled = True
         self.init_log()
         self.init_debugger()
         self.init_svg()
 
     def init_log(self):
-        self.log_file = os.path.join(os.path.dirname(os.path.dirname(__file__)), "debug.log")
+        self.log_file = self.debug_dir / self.debug_log_file
         # delete old content
-        with open(self.log_file, "w"):
+        with self.log_file.open("w"):
             pass
         self.log("Debug logging enabled.")
 
     def init_debugger(self):
-        # How to debug Ink/Stitch with LiClipse:
+        ### General debugging notes:
+        # 1. to enable debugging or profiling copy DEBUG_template.ini to DEBUG.ini and edit it
+
+        ### How create bash script for offline debugging from console
+        # 1. in DEBUG.ini set create_bash_script = True
+        # 2. call inkstitch.py extension from inkscape to create bash script named by bash_file_base in DEBUG.ini
+        # 3. run bash script from console
+
+        ### Enable debugging
+        # 1. set debug_type to one of  - vscode, pycharm, pydev, see below for details
+        #      debug_type = vscode    - 'debugpy' for vscode editor 
+        #      debug_type = pycharm   - 'pydevd-pycharm' for pycharm editor
+        #      debug_type = pydev     - 'pydevd' for eclipse editor
+        # 2. set debug_enable = True in DEBUG.ini
+        #    or use command line argument -d in bash script
+        #    or set environment variable INKSTITCH_DEBUG_ENABLE = True or 1 or yes or y
+
+        ### Enable profiling
+        # 1. set profiler_type to one of - cprofile, profile, pyinstrument
+        #      profiler_type = cprofile    - 'cProfile' profiler
+        #      profiler_type = profile     - 'profile' profiler
+        #      profiler_type = pyinstrument- 'pyinstrument' profiler
+        # 2. set profile_enable = True in DEBUG.ini
+        #    or use command line argument -p in bash script
+        #    or set environment variable INKSTITCH_PROFILE_ENABLE = True or 1 or yes or y
+
+        ### Miscelaneous notes:
+        # - to disable debugger when running from inkscape set disable_from_inkscape = True in DEBUG.ini
+        # - to write debug output to file set debug_to_file = True in DEBUG.ini
+        # - to change various output file names see DEBUG.ini
+        # - to disable waiting for debugger to attach (vscode editor) set wait_attach = False in DEBUG.ini
+        # - to prefer inkscape version of inkex module over pip version set prefer_pip_inkex = False in DEBUG.ini
+
+        ###
+
+
+        ### How to debug Ink/Stitch with LiClipse:
         #
         # 1. Install LiClipse (liclipse.com) -- no need to install Eclipse first
         # 2. Start debug server as described here: http://www.pydev.org/manual_adv_remote_debugger.html
         #    * follow the "Note:" to enable the debug server menu item
-        # 3. Create a file named "DEBUG" next to inkstitch.py in your git clone.
+        # 3. Copy and edit a file named "DEBUG.ini" from "DEBUG_template.ini" next to inkstitch.py in your git clone
+        #    and set debug_type = pydev
         # 4. Run any extension and PyDev will start debugging.
 
         ###
 
-        # To debug with PyCharm:
+        ### To debug with PyCharm:
 
         # You must use the PyCharm Professional Edition and _not_ the Community
         # Edition. Jetbrains has chosen to make remote debugging a Pro feature.
@@ -112,7 +169,8 @@ class Debug(object):
         #    configuration. Set "IDE host name:" to  "localhost" and "Port:" to 5678.
         #    You can leave the default settings for all other choices.
         #
-        # 3. Touch a file named "DEBUG" at the top of your git repo, as above.
+        # 3. Touch a file named "DEBUG.ini" at the top of your git repo, as above
+        #    set debug_type = pycharm
         #
         # 4. Create a symbolic link in the Inkscape extensions directory to the
         #    top-level directory of your git repo. On a mac, for example:
@@ -125,29 +183,62 @@ class Debug(object):
         #    extensions directory, or you'll see duplicate entries in the Ink/Stitch
         #    extensions menu in Inkscape.
         #
-        # 5. In the execution env for Inkscape, set the environment variable
-        #    PYCHARM_REMOTE_DEBUG to any value, and launch Inkscape. If you're starting
-        #    Inkscape from the PyCharm Terminal pane, you can do:
-        #        export PYCHARM_REMOTE_DEBUG=true;inkscape
-        #
-        # 6. In Pycharm, either click on the green "bug" icon if visible in the upper
+        # 5. In Pycharm, either click on the green "bug" icon if visible in the upper
         #    right or press Ctrl-D to start debugging.The PyCharm debugger pane will
         #    display the message "Waiting for process connection..."
         #
-        # 7. Do some action in Inkscape which invokes Ink/Stitch extension code, and the
+        # 6. Do some action in Inkscape which invokes Ink/Stitch extension code, and the
         #    debugger will be triggered. If you've left "Suspend after connect" checked
         #    in the Run configuration, PyCharm will pause in the "self.log("Enabled
         #    PyDev debugger.)" statement, below. Uncheck the box to have it continue
         #    automatically to your first set breakpoint.
 
+        ###
+
+        ### To debug with VS Code
+        # see: https://code.visualstudio.com/docs/python/debugging#_command-line-debugging
+        #      https://code.visualstudio.com/docs/python/debugging#_debugging-by-attaching-over-a-network-connection
+        # 
+        # 1. Install the Python extension for VS Code
+        #      pip install debugpy
+        # 2. create .vscode/launch.json containing:
+        #       "configurations": [ ...
+        #           {
+        #               "name": "Python: Attach",
+        #               "type": "python",
+        #               "request": "attach",
+        #               "connect": {
+        #                 "host": "localhost",
+        #                 "port": 5678
+        #               }
+        #           }
+        #       ]
+        # 3. Touch a file named "DEBUG.ini" at the top of your git repo, as above
+        #    set debug_type = vscode
+        # 4. Start the debug server in VS Code by clicking on the debug icon in the left pane
+        #    select "Python: Attach" from the dropdown menu and click on the green arrow.
+        #    The debug server will start and connect to already running python processes,
+        #    but immediately exit if no python processes are running.
+        #
+        # Notes:
+        #   to see flask server url routes:
+        #      - comment out the line self.disable_logging() in run() of lib/api/server.py
+                
+
         try:
-            if 'PYCHARM_REMOTE_DEBUG' in os.environ:
+            if self.debugger == 'vscode':
+                import debugpy
+            elif self.debugger == 'pycharm':
                 import pydevd_pycharm
-            else:
+            elif self.debugger == 'pydev':
                 import pydevd
+            elif self.debugger == 'file':
+                pass
+            else:
+                raise ValueError(f"unknown debugger: '{self.debugger}'")
 
         except ImportError:
-            self.log("importing pydevd failed (debugger disabled)")
+            self.log(f"importing debugger failed (debugger disabled) for {self.debugger}")
 
         # pydevd likes to shout about errors to stderr whether I want it to or not
         with open(os.devnull, 'w') as devnull:
@@ -155,17 +246,27 @@ class Debug(object):
             sys.stderr = devnull
 
             try:
-                if 'PYCHARM_REMOTE_DEBUG' in os.environ:
+                if self.debugger == 'vscode':
+                    debugpy.listen(('localhost', 5678))
+                    if self.wait_attach:
+                        print("Waiting for debugger attach")
+                        debugpy.wait_for_client()        # wait for debugger to attach
+                        debugpy.breakpoint()             # stop here to start normal debugging
+                elif self.debugger == 'pycharm':
                     pydevd_pycharm.settrace('localhost', port=5678, stdoutToServer=True,
                                             stderrToServer=True)
-                else:
+                elif self.debugger == 'pydev':
                     pydevd.settrace()
+                elif self.debugger == 'file':
+                    pass
+                else:
+                    raise ValueError(f"unknown debugger: '{self.debugger}'")
 
             except socket.error as error:
                 self.log("Debugging: connection to pydevd failed: %s", error)
-                self.log("Be sure to run 'Start debugging server' in PyDev to enable debugging.")
+                self.log(f"Be sure to run 'Start debugging server' in {self.debugger} to enable debugging.")
             else:
-                self.log("Enabled PyDev debugger.")
+                self.log(f"Enabled '{self.debugger}' debugger.")
 
             sys.stderr = stderr
 
@@ -175,8 +276,8 @@ class Debug(object):
 
     def save_svg(self):
         tree = etree.ElementTree(self.svg)
-        debug_svg = os.path.join(os.path.dirname(os.path.dirname(__file__)), "debug.svg")
-        tree.write(debug_svg)
+        debug_svg = self.debug_dir / self.debug_svg_file
+        tree.write(str(debug_svg))    # lxml <5.0.0 does not support Path objects
 
     @check_enabled
     @unwrap_arguments
@@ -218,20 +319,21 @@ class Debug(object):
         timestamp = now.isoformat()
         self.last_log_time = now
 
-        with open(self.log_file, "a") as logfile:
+        with self.log_file.open("a") as logfile:
             print(timestamp, message % args, file=logfile)
             logfile.flush()
 
+    # decorator to measure time of function
     def time(self, func):
         def decorated(*args, **kwargs):
             if self.enabled:
                 self.raw_log("entering %s()", func.__name__)
-                start = time.time()
+                start = time.monotonic()
 
             result = func(*args, **kwargs)
 
             if self.enabled:
-                end = time.time()
+                end = time.monotonic()
                 self.raw_log("leaving %s(), duration = %s", func.__name__, round(end - start, 6))
 
             return result
@@ -299,20 +401,19 @@ class Debug(object):
             INKSCAPE_LABEL: name
         }))
 
+    # decorator to measure time of with block
     @contextmanager
     def time_this(self, label="code block"):
         if self.enabled:
-            start = time.time()
+            start = time.monotonic()
             self.raw_log("begin %s", label)
 
         yield
 
         if self.enabled:
-            self.raw_log("completed %s, duration = %s", label, time.time() - start)
+            self.raw_log("completed %s, duration = %s", label, time.monotonic() - start)
 
 
+# global debug object
 debug = Debug()
 
-
-def enable():
-    debug.enable()
diff --git a/lib/debug_utils.py b/lib/debug_utils.py
new file mode 100644
index 00000000..169fa4c5
--- /dev/null
+++ b/lib/debug_utils.py
@@ -0,0 +1,231 @@
+# Authors: see git history
+#
+# Copyright (c) 2010 Authors
+# Licensed under the GNU GPL version 3.0 or later.  See the file LICENSE for details.
+
+import os
+import sys
+from pathlib import Path  # to work with paths as objects
+import configparser       # to read DEBUG.ini
+
+# this file is without: import inkex
+# - we need dump argv and sys.path as is on startup from inkscape
+#   - later sys.path may be modified that influences importing inkex (see prefere_pip_inkex)
+
+
+def write_offline_debug_script(debug_script_dir : Path, ini : configparser.ConfigParser):
+    '''
+    prepare Bash script for offline debugging from console
+        arguments:
+        - debug_script_dir - Path object, absolute path to directory of inkstitch.py
+        - ini       - see DEBUG.ini
+    '''
+
+    # define names of files used by offline Bash script
+    bash_file_base = ini.get("DEBUG","bash_file_base", fallback="debug_inkstitch")
+    bash_name = Path(bash_file_base).with_suffix(".sh")  # Path object
+    bash_svg  = Path(bash_file_base).with_suffix(".svg") # Path object
+
+    # check if input svg file exists in arguments, take argument that not start with '-' as file name
+    svgs = [arg for arg in sys.argv[1:] if not arg.startswith('-')]
+    if len(svgs) != 1:
+        print(f"WARN: {len(svgs)} svg files found, expected 1, [{svgs}]. No script created in write debug script.", file=sys.stderr)
+        return
+
+    svg_file = Path(svgs[0])
+    if svg_file.exists() and bash_svg.exists() and bash_svg.samefile(svg_file):
+        print(f"WARN: input svg file is same as output svg file. No script created in write debug script.", file=sys.stderr)
+        return
+    
+    import shutil  # to copy svg file
+    bash_file = debug_script_dir / bash_name
+
+    with open(bash_file, 'w') as f:  # "w" text mode, automatic conversion of \n to os.linesep
+        f.write(f'#!/usr/bin/env bash\n')
+
+        # cmd line arguments for debugging and profiling
+        f.write(bash_parser())  # parse cmd line arguments: -d -p
+
+        f.write(f'# python version: {sys.version}\n')   # python version
+        
+        myargs = " ".join(sys.argv[1:])
+        f.write(f'# script: {sys.argv[0]}  arguments: {myargs}\n') # script name and arguments
+
+        # environment PATH
+        f.write(f'# PATH:\n')
+        f.write(f'#   {os.environ.get("PATH","")}\n')
+        # for p in os.environ.get("PATH", '').split(os.pathsep): # PATH to list
+        #     f.write(f'#   {p}\n')
+
+        # python module path
+        f.write(f'# python sys.path:\n')
+        for p in sys.path:
+            f.write(f'#   {p}\n')
+
+        # see static void set_extensions_env() in inkscape/src/inkscape-main.cpp
+        f.write(f'# PYTHONPATH:\n')
+        for p in os.environ.get('PYTHONPATH', '').split(os.pathsep): # PYTHONPATH to list
+            f.write(f'#   {p}\n')
+
+        f.write(f'# copy {svg_file} to {bash_svg}\n#\n')
+        shutil.copy(svg_file, debug_script_dir / bash_svg)  # copy file to bash_svg
+        myargs = myargs.replace(str(svg_file), str(bash_svg))   # replace file name with bash_svg
+
+        # see void Extension::set_environment() in inkscape/src/extension/extension.cpp
+        f.write('# Export inkscape environment variables:\n')
+        notexported = ['SELF_CALL'] # if an extension calls inkscape itself
+        exported = ['INKEX_GETTEXT_DOMAIN', 'INKEX_GETTEXT_DIRECTORY', 
+                    'INKSCAPE_PROFILE_DIR', 'DOCUMENT_PATH', 'PYTHONPATH']
+        for k in notexported:
+            if k in os.environ:
+                f.write(f'#   export {k}="{os.environ[k]}"\n')
+        for k in exported:
+            if k in os.environ:
+                f.write(f'export {k}="{os.environ[k]}"\n')
+
+        f.write('# signal inkstitch.py that we are running from offline script\n')
+        f.write(f'export INKSTITCH_OFFLINE_SCRIPT="True"\n')
+
+        f.write('# call inkstitch\n')
+        f.write(f'python3 inkstitch.py {myargs}\n')
+    bash_file.chmod(0o0755)  # make file executable, hopefully ignored on Windows
+
+
+def bash_parser():
+    return '''
+set -e   #  exit on error
+
+# parse cmd line arguments:
+#   -d enable debugging
+#   -p enable profiling
+#             ":..." - silent error reporting
+while getopts ":dp" opt; do
+  case $opt in
+    d)
+        arg_d="true"
+        ;;
+    p)
+        arg_p="true"
+        ;;
+    \?)
+        echo "Invalid option: -$OPTARG" >&2
+        exit 1
+        ;;
+    :)
+        echo "Option -$OPTARG requires an argument." >&2
+        exit 1
+        ;;
+  esac
+done
+
+#     -v: check if variable is set
+if [[ -v arg_d ]]; then
+    export INKSTITCH_DEBUG_ENABLE="True"
+fi
+if [[ -v arg_p ]]; then
+    export INKSTITCH_PROFILE_ENABLE="True"
+fi
+
+'''
+
+
+def reorder_sys_path():
+    '''
+    change sys.path to prefer pip installed inkex over inkscape bundled inkex
+    '''
+
+    # see static void set_extensions_env() in inkscape/src/inkscape-main.cpp
+    # what we do:
+    # - move inkscape extensions path to the end of sys.path
+    # - we compare PYTHONPATH with sys.path and move PYTHONPATH to the end of sys.path
+    #   - also user inkscape extensions path is moved to the end of sys.path - may cause problems?
+    #   - path for deprecated-simple are removed from sys.path, will be added later by importing inkex
+
+    # PYTHONPATH to list
+    pythonpath = os.environ.get('PYTHONPATH', '').split(os.pathsep)
+    # remove pythonpath from sys.path
+    sys.path = [p for p in sys.path if p not in pythonpath]
+    # remove deprecated-simple, it will be added later by importing inkex
+    pythonpath = [p for p in pythonpath if not p.endswith('deprecated-simple')]
+    # remove nonexisting paths
+    pythonpath = [p for p in pythonpath if os.path.exists(p)]
+    # add pythonpath to the end of sys.path
+    sys.path.extend(pythonpath)
+
+# -----------------------------------------------------------------------------
+# Profilers:
+# currently supported profilers:
+# - cProfile - standard python profiler
+# - profile  - standard python profiler
+# - pyinstrument - profiler with nice html output
+    
+
+def profile(profiler_type, profile_dir : Path, ini : configparser.ConfigParser, extension, remaining_args):
+    '''
+    profile with cProfile, profile or pyinstrument
+    '''
+    profile_file_base = ini.get("PROFILE","profile_file_base", fallback="debug_profile")
+    profile_file_path = profile_dir / profile_file_base  # Path object
+
+    if profiler_type == 'cprofile':
+        with_cprofile(extension, remaining_args, profile_file_path)
+    elif profiler_type == 'profile':
+        with_profile(extension, remaining_args, profile_file_path)
+    elif profiler_type == 'pyinstrument':
+        with_pyinstrument(extension, remaining_args, profile_file_path)
+    else:
+        raise ValueError(f"unknown profiler type: '{profiler_type}'")
+
+def with_cprofile(extension, remaining_args, profile_file_path):
+    '''
+    profile with cProfile
+    '''
+    import cProfile
+    import pstats
+    profiler = cProfile.Profile()
+
+    profiler.enable()
+    extension.run(args=remaining_args)
+    profiler.disable()
+
+    profiler.dump_stats(profile_file_path.with_suffix(".prof"))  # can be read by 'snakeviz -s' or 'pyprof2calltree'
+    with open(profile_file_path, 'w') as stats_file:
+        stats = pstats.Stats(profiler, stream=stats_file)
+        stats.sort_stats(pstats.SortKey.CUMULATIVE)
+        stats.print_stats()
+    print(f"Profiler: cprofile, stats written to '{profile_file_path.name}' and '{profile_file_path.name}.prof'. Use snakeviz to see it.", 
+          file=sys.stderr)
+
+def with_profile(extension, remaining_args, profile_file_path):
+    '''
+    profile with profile
+    '''
+    import profile
+    import pstats
+    profiler = profile.Profile()
+
+    profiler.run('extension.run(args=remaining_args)')
+
+    profiler.dump_stats(profile_file_path.with_suffix(".prof"))  # can be read by 'snakeviz' or 'pyprof2calltree' - seems broken
+    with open(profile_file_path, 'w') as stats_file:
+        stats = pstats.Stats(profiler, stream=stats_file)
+        stats.sort_stats(pstats.SortKey.CUMULATIVE)
+        stats.print_stats()
+    print(f"'Profiler: profile, stats written to '{profile_file_path.name}' and '{profile_file_path.name}.prof'. Use of snakeviz is broken.", 
+          file=sys.stderr)
+
+def with_pyinstrument(extension, remaining_args, profile_file_path):
+    '''
+    profile with pyinstrument
+    '''
+    import pyinstrument
+    profiler = pyinstrument.Profiler()
+
+    profiler.start()
+    extension.run(args=remaining_args)
+    profiler.stop()
+
+    profile_file_path = profile_file_path.with_suffix(".html")
+    with open(profile_file_path, 'w') as stats_file:
+        stats_file.write(profiler.output_html())
+    print(f"Profiler: pyinstrument, stats written to '{profile_file_path.name}'. Use browser to see it.", file=sys.stderr)