Investigating slow execution in 6.0b2 debugger

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

Investigating slow execution in 6.0b2 debugger

WingIDE - User mailing list
Hi folks,

Setting aside my other thread about mysterious extraneous execution when the debugger is *stopped*, this question is about slowness of *running* code in the debugger.

In particular, the 6.0 debugger seems substantially slower than the 5.1.12 debugger.

Again the example is a time-hogging section of Django initial startup code, in which the cascade of imports leads to compiling a very complicated regex for validating URLs (using the Python standard re library).

Django 1.8.14.  Python 3.5.2 on Windows 7-64.

That re.compile([complicated regex]) call takes (stopwatch):

6.0b2  debugger: about 20 secs.
5.1.12 debugger: about 4.6 sec
Command-line: < 1sec

I have isolated this particular code into a stand-alone module that just calls re.compile([complicated regex]).  Attached below.

Standalone module profiler times
6.0 debugger: about  4.5 secs
5.1 debugger: about  1.7 sec
Command line  about 0.34 sec

Obviously this raises two issues:

Question 1. 6.0 debugger environment seems a factor of 3 or 4 slower than 5.1. Any chance this is a setting somewhere?

Question 2. Why does the code run so much slower as part of Django's startup compared to in a stand-alone module?

For what it's worth, the slow parts of the sre_compile.py code are:

-- _optimize_charset(); of the 25 calls, almost all time is while processing the ~65k character sets in the 'ul' pattern, which gets included five times in the overall regex, and includes...

-- the 327k calls to fixup() (... get_lower())

So one could certainly criticize this library for doing so much work (essentially reprocessing the time-consuming pattern five times.)

Yet it seems to be "good enough" when run from command line.

One possible clue from the profiler output (attached below): The 6.0 debugger seems to cause the calls to fixup() to be very much disproportionately slower than any other part of the profile compared to the 5.1 profile.

=======================================
Reference section
=======================================

The test module code (originally from Django validators.py):

------------------------------------------------------------
import cProfile
import re

ul = '\u00a1-\uffff'  # unicode letters range (must be a unicode string, not a raw string)

# IP patterns
ipv4_re = r'(?:25[0-5]|2[0-4]\d|[0-1]?\d?\d)(?:\.(?:25[0-5]|2[0-4]\d|[0-1]?\d?\d)){3}'
ipv6_re = r'\[[0-9a-f:\.]+\]'  # (simple regex, validated later)

# Host patterns
hostname_re = r'[a-z' + ul + r'0-9](?:[a-z' + ul + r'0-9-]*[a-z' + ul + r'0-9])?'
domain_re = r'(?:\.(?!-)[a-z' + ul + r'0-9-]+(?<!-))*'
tld_re = (
    '\.'                                # dot
    '(?!-)'                             # can't start with a dash
    '(?:[a-z' + ul + '-]{2,}'           # domain label
    '|xn--[a-z0-9]+)'                   # or punycode label
    '(?<!-)'                            # can't end with a dash
    '\.?'                               # may have a trailing dot
)
host_re = '(' + hostname_re + domain_re + tld_re + '|localhost)'

regex1 = (r'^(?:[a-z0-9\.\-]*)://'  # scheme is validated separately
    r'(?:\S+(?::\S*)?@)?'  # user:pass authentication
    r'(?:' + ipv4_re + '|' + ipv6_re + '|' + host_re + ')'
    r'(?::\d{2,5})?'  # port
    r'(?:[/?#][^\s]*)?'  # resource path
    r'\Z')

print("")
print('--- Start ---')
print(regex1) # OK in Debug window, fails on Windows console due to unicode

code_to_run = r"re.compile(regex1, re.IGNORECASE )"
cProfile.run(code_to_run)

# re.compile(regex1, re.IGNORECASE )

print('--- end ---')
------------------------------------------------------------

====================
Profiler outputs:
====================

---------------------------------------
WingIDE 5.1.12 Debugger
cProfile output

         657771 function calls (657602 primitive calls) in 1.776 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.776    1.776 <string>:1(<module>)
        1    0.000    0.000    1.776    1.776 re.py:223(compile)
        1    0.000    0.000    1.776    1.776 re.py:290(_compile)
   327232    0.594    0.000    0.686    0.000 sre_compile.py:101(fixup)
       25    0.000    0.000    1.763    0.071 sre_compile.py:221(_compile_charset)
       25    1.074    0.043    1.763    0.071 sre_compile.py:248(_optimize_charset)
        9    0.000    0.000    0.001    0.000 sre_compile.py:378(_mk_bitmap)
        9    0.001    0.000    0.001    0.000 sre_compile.py:380(<listcomp>)
        7    0.000    0.000    0.000    0.000 sre_compile.py:383(_bytes_to_codes)
       22    0.000    0.000    0.000    0.000 sre_compile.py:390(_simple)
        1    0.000    0.000    0.001    0.001 sre_compile.py:416(_compile_info)
        2    0.000    0.000    0.000    0.000 sre_compile.py:517(isstring)
        1    0.000    0.000    1.767    1.767 sre_compile.py:520(_code)
        1    0.000    0.000    1.776    1.776 sre_compile.py:535(compile)
     53/1    0.002    0.000    1.766    1.766 sre_compile.py:64(_compile)
       57    0.000    0.000    0.000    0.000 sre_constants.py:49(__str__)
       53    0.000    0.000    0.000    0.000 sre_parse.py:105(__init__)
       83    0.000    0.000    0.000    0.000 sre_parse.py:153(__len__)
      242    0.001    0.000    0.001    0.000 sre_parse.py:157(__getitem__)
       22    0.000    0.000    0.000    0.000 sre_parse.py:161(__setitem__)
       84    0.000    0.000    0.000    0.000 sre_parse.py:165(append)
    74/26    0.001    0.000    0.001    0.000 sre_parse.py:167(getwidth)
        1    0.000    0.000    0.000    0.000 sre_parse.py:217(__init__)
      276    0.002    0.000    0.002    0.000 sre_parse.py:226(__next)
      141    0.000    0.000    0.001    0.000 sre_parse.py:242(match)
      202    0.001    0.000    0.002    0.000 sre_parse.py:247(get)
       73    0.000    0.000    0.000    0.000 sre_parse.py:276(tell)
        4    0.000    0.000    0.000    0.000 sre_parse.py:312(_class_escape)
       16    0.000    0.000    0.000    0.000 sre_parse.py:362(_escape)
     18/1    0.001    0.000    0.009    0.009 sre_parse.py:429(_parse_sub)
     26/1    0.003    0.000    0.009    0.009 sre_parse.py:491(_parse)
        1    0.000    0.000    0.000    0.000 sre_parse.py:70(__init__)
        6    0.000    0.000    0.000    0.000 sre_parse.py:75(groups)
        1    0.000    0.000    0.000    0.000 sre_parse.py:78(opengroup)
        1    0.000    0.000    0.000    0.000 sre_parse.py:797(fix_flags)
        1    0.000    0.000    0.009    0.009 sre_parse.py:819(parse)
        1    0.000    0.000    0.001    0.001 sre_parse.py:90(closegroup)
        1    0.000    0.000    0.000    0.000 {built-in method _sre.compile}
   327267    0.092    0.000    0.092    0.000 {built-in method _sre.getlower}
        1    0.000    0.000    1.776    1.776 {built-in method builtins.exec}
      247    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
  486/459    0.000    0.000    0.000    0.000 {built-in method builtins.len}
       13    0.000    0.000    0.000    0.000 {built-in method builtins.max}
      116    0.000    0.000    0.000    0.000 {built-in method builtins.min}
       97    0.000    0.000    0.000    0.000 {built-in method builtins.ord}
       32    0.001    0.000    0.001    0.000 {built-in method builtins.print}
      599    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        7    0.000    0.000    0.000    0.000 {method 'cast' of 'memoryview' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        9    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
       73    0.000    0.000    0.000    0.000 {method 'find' of 'bytearray' objects}
       32    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
        7    0.000    0.000    0.000    0.000 {method 'tolist' of 'memoryview' objects}
        9    0.000    0.000    0.000    0.000 {method 'translate' of 'bytearray' objects}

---------------------------------------
WingIDE 6.0b2 Debugger
cProfile output

         657771 function calls (657602 primitive calls) in 4.387 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    4.387    4.387 <string>:1(<module>)
        1    0.000    0.000    4.387    4.387 re.py:223(compile)
        1    0.000    0.000    4.387    4.387 re.py:290(_compile)
   327232    3.035    0.000    3.124    0.000 sre_compile.py:101(fixup)
       25    0.000    0.000    4.371    0.175 sre_compile.py:221(_compile_charset)
       25    1.245    0.050    4.370    0.175 sre_compile.py:248(_optimize_charset)
        9    0.000    0.000    0.001    0.000 sre_compile.py:378(_mk_bitmap)
        9    0.001    0.000    0.001    0.000 sre_compile.py:380(<listcomp>)
        7    0.000    0.000    0.000    0.000 sre_compile.py:383(_bytes_to_codes)
       22    0.000    0.000    0.000    0.000 sre_compile.py:390(_simple)
        1    0.000    0.000    0.001    0.001 sre_compile.py:416(_compile_info)
        2    0.000    0.000    0.000    0.000 sre_compile.py:517(isstring)
        1    0.000    0.000    4.375    4.375 sre_compile.py:520(_code)
        1    0.000    0.000    4.387    4.387 sre_compile.py:535(compile)
     53/1    0.002    0.000    4.375    4.375 sre_compile.py:64(_compile)
       57    0.000    0.000    0.000    0.000 sre_constants.py:49(__str__)
       53    0.000    0.000    0.000    0.000 sre_parse.py:105(__init__)
       83    0.000    0.000    0.000    0.000 sre_parse.py:153(__len__)
      242    0.002    0.000    0.002    0.000 sre_parse.py:157(__getitem__)
       22    0.000    0.000    0.000    0.000 sre_parse.py:161(__setitem__)
       84    0.000    0.000    0.000    0.000 sre_parse.py:165(append)
    74/26    0.001    0.000    0.001    0.000 sre_parse.py:167(getwidth)
        1    0.000    0.000    0.000    0.000 sre_parse.py:217(__init__)
      276    0.002    0.000    0.002    0.000 sre_parse.py:226(__next)
      141    0.001    0.000    0.001    0.000 sre_parse.py:242(match)
      202    0.002    0.000    0.003    0.000 sre_parse.py:247(get)
       73    0.000    0.000    0.000    0.000 sre_parse.py:276(tell)
        4    0.000    0.000    0.000    0.000 sre_parse.py:312(_class_escape)
       16    0.000    0.000    0.000    0.000 sre_parse.py:362(_escape)
     18/1    0.001    0.000    0.011    0.011 sre_parse.py:429(_parse_sub)
     26/1    0.003    0.000    0.011    0.011 sre_parse.py:491(_parse)
        1    0.000    0.000    0.000    0.000 sre_parse.py:70(__init__)
        6    0.000    0.000    0.000    0.000 sre_parse.py:75(groups)
        1    0.000    0.000    0.000    0.000 sre_parse.py:78(opengroup)
        1    0.000    0.000    0.000    0.000 sre_parse.py:797(fix_flags)
        1    0.000    0.000    0.011    0.011 sre_parse.py:819(parse)
        1    0.000    0.000    0.000    0.000 sre_parse.py:90(closegroup)
        1    0.000    0.000    0.000    0.000 {built-in method _sre.compile}
   327267    0.089    0.000    0.089    0.000 {built-in method _sre.getlower}
        1    0.000    0.000    4.387    4.387 {built-in method builtins.exec}
      247    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
  486/459    0.000    0.000    0.000    0.000 {built-in method builtins.len}
       13    0.000    0.000    0.000    0.000 {built-in method builtins.max}
      116    0.000    0.000    0.000    0.000 {built-in method builtins.min}
       97    0.000    0.000    0.000    0.000 {built-in method builtins.ord}
       32    0.001    0.000    0.001    0.000 {built-in method builtins.print}
      599    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        7    0.000    0.000    0.000    0.000 {method 'cast' of 'memoryview' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        9    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
       73    0.000    0.000    0.000    0.000 {method 'find' of 'bytearray' objects}
       32    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
        7    0.000    0.000    0.000    0.000 {method 'tolist' of 'memoryview' objects}
        9    0.000    0.000    0.000    0.000 {method 'translate' of 'bytearray' objects}

-----------------------------------
Command line cProfile output

         657899 function calls (657730 primitive calls) in 0.336 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.336    0.336 <string>:1(<module>)
       64    0.000    0.000    0.000    0.000 cp1252.py:18(encode)
        1    0.000    0.000    0.336    0.336 re.py:223(compile)
        1    0.000    0.000    0.336    0.336 re.py:290(_compile)
   327232    0.096    0.000    0.176    0.000 sre_compile.py:101(fixup)
       25    0.000    0.000    0.333    0.013 sre_compile.py:221(_compile_charset)
       25    0.156    0.006    0.333    0.013 sre_compile.py:248(_optimize_charset)
        9    0.000    0.000    0.001    0.000 sre_compile.py:378(_mk_bitmap)
        9    0.001    0.000    0.001    0.000 sre_compile.py:380(<listcomp>)
        7    0.000    0.000    0.000    0.000 sre_compile.py:383(_bytes_to_codes)
       22    0.000    0.000    0.000    0.000 sre_compile.py:390(_simple)
        1    0.000    0.000    0.000    0.000 sre_compile.py:416(_compile_info)
        2    0.000    0.000    0.000    0.000 sre_compile.py:517(isstring)
        1    0.000    0.000    0.334    0.334 sre_compile.py:520(_code)
        1    0.000    0.000    0.336    0.336 sre_compile.py:535(compile)
     53/1    0.000    0.000    0.334    0.334 sre_compile.py:64(_compile)
       57    0.000    0.000    0.000    0.000 sre_constants.py:49(__str__)
       53    0.000    0.000    0.000    0.000 sre_parse.py:105(__init__)
       83    0.000    0.000    0.000    0.000 sre_parse.py:153(__len__)
      242    0.000    0.000    0.000    0.000 sre_parse.py:157(__getitem__)
       22    0.000    0.000    0.000    0.000 sre_parse.py:161(__setitem__)
       84    0.000    0.000    0.000    0.000 sre_parse.py:165(append)
    74/26    0.000    0.000    0.000    0.000 sre_parse.py:167(getwidth)
        1    0.000    0.000    0.000    0.000 sre_parse.py:217(__init__)
      276    0.000    0.000    0.000    0.000 sre_parse.py:226(__next)
      141    0.000    0.000    0.000    0.000 sre_parse.py:242(match)
      202    0.000    0.000    0.000    0.000 sre_parse.py:247(get)
       73    0.000    0.000    0.000    0.000 sre_parse.py:276(tell)
        4    0.000    0.000    0.000    0.000 sre_parse.py:312(_class_escape)
       16    0.000    0.000    0.000    0.000 sre_parse.py:362(_escape)
     18/1    0.000    0.000    0.002    0.002 sre_parse.py:429(_parse_sub)
     26/1    0.001    0.000    0.002    0.002 sre_parse.py:491(_parse)
        1    0.000    0.000    0.000    0.000 sre_parse.py:70(__init__)
        6    0.000    0.000    0.000    0.000 sre_parse.py:75(groups)
        1    0.000    0.000    0.000    0.000 sre_parse.py:78(opengroup)
        1    0.000    0.000    0.000    0.000 sre_parse.py:797(fix_flags)
        1    0.000    0.000    0.002    0.002 sre_parse.py:819(parse)
        1    0.000    0.000    0.000    0.000 sre_parse.py:90(closegroup)
       64    0.000    0.000    0.000    0.000 {built-in method _codecs.charmap_encode}
        1    0.000    0.000    0.000    0.000 {built-in method _sre.compile}
   327267    0.080    0.000    0.080    0.000 {built-in method _sre.getlower}
        1    0.000    0.000    0.336    0.336 {built-in method builtins.exec}
      247    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
  486/459    0.000    0.000    0.000    0.000 {built-in method builtins.len}
       13    0.000    0.000    0.000    0.000 {built-in method builtins.max}
      116    0.000    0.000    0.000    0.000 {built-in method builtins.min}
       97    0.000    0.000    0.000    0.000 {built-in method builtins.ord}
       32    0.000    0.000    0.001    0.000 {built-in method builtins.print}
      599    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        7    0.000    0.000    0.000    0.000 {method 'cast' of 'memoryview' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        9    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
       73    0.000    0.000    0.000    0.000 {method 'find' of 'bytearray' objects}
       32    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
        7    0.000    0.000    0.000    0.000 {method 'tolist' of 'memoryview' objects}
        9    0.000    0.000    0.000    0.000 {method 'translate' of 'bytearray' objects}



 

_________________________________________________
Wing IDE users list
http://wingware.com/lists/wingide
Reply | Threaded
Open this post in threaded view
|

Re: Investigating slow execution in 6.0b2 debugger

WingIDE - User mailing list
On 9/27/16 5:26 AM, Graham Wideman via wingide-users wrote:
> In particular, the 6.0 debugger seems substantially slower than the 5.1.12 debugger.
>
> Again the example is a time-hogging section of Django initial startup code, in which the cascade of imports leads to compiling a very complicated regex for validating URLs (using the Python standard re library).

It is slow in the debugger with python 3.5 (and probably python 3.x).
Interestingly, it performs reasonably in the debugger with python 2.7.

We'll try to fix this soon.

Thanks,

John
_________________________________________________
Wing IDE users list
http://wingware.com/lists/wingide