When using pyre2
(https://github.com/axiak/pyre2), I encountered a performance problem (matching time).
I have three programs:
pure Python using built-in re module: https://gist.github.com/1873402
Python using Pyre2: https://gist.github.com/1873402. (Most part of the code is the same as no.1 program. Except when using built-in re, it will decode utf-8 string to unicode, which is NOT necessary when using pyre2)
C/C++ using re2: https://gist.github.com/1873417
I measured two time: regex pre-compile time and matching time.
no.1 program: 1.65s 1.25s
no.2 program: 0.04s 1.8s
no.3 program: 0.02s 0.8s
They all feed by the same regex and input. (All regexes are supported by re2
)
Then I followed the documentation about profiling in Cython. Got the following result:
ncalls tottime percall cumtime percall filename:lineno(function) 652884 16.477 0.000 25.349 0.000 re2.pyx:394(_search) 9479 6.059 0.001 41.806 0.004 export_plain.py:60(match) 652884 4.243 0.000 33.602 0.000 {method 'search' of 're2.Pattern' objects} 652884 4.010 0.000 29.359 0.000 re2.pyx:442(search) 652884 3.056 0.000 3.056 0.000 re2.pyx:114(__init__) 652953 2.145 0.000 2.145 0.000 {isinstance} 652884 2.002 0.000 2.002 0.000 re2.pyx:123(__dealloc__) 652953 1.911 0.000 1.911 0.000 re2.pyx:75(unicode_to_bytestring) 652953 1.902 0.000 1.902 0.000 re2.pyx:86(pystring_to_bytestring) 1 0.330 0.330 42.492 42.492 export_plain.py:98(export_fname) 9479 0.173 0.000 0.173 0.000 {built-in method sub} 10000 0.120 0.000 0.120 0.000 {method 'split' of 'str' objects} 8967 0.063 0.000 0.099 0.000 re2.pyx:801(get) 10069 0.061 0.000 0.061 0.000 {method 'strip' of 'str' objects} 69 0.043 0.001 0.146 0.002 re2.pyx:806(prepare_pattern) 9036 0.038 0.000 0.038 0.000 re2.pyx:788(__next) 69 0.022 0.000 0.169 0.002 re2.pyx:905(_compile) 1 0.005 0.005 0.177 0.177 export_plain.py:36(load) 69 0.002 0.000 0.003 0.000 re2.pyx:784(__init__) 69 0.001 0.000 0.170 0.002 re2.pyx:763(compile) 38 0.001 0.000 0.001 0.000 {method 'write' of 'file' objects} 69 0.001 0.000 0.171 0.002 {re2.compile} 1 0.001 0.001 42.669 42.669 export_plain.py:160(main) 3 0.000 0.000 0.000 0.000 {open} 69 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects} 19 0.000 0.000 0.000 0.000 {method 'join' of 'str' objects} 1 0.000 0.000 0.000 0.000 genericpath.py:38(isdir) 1 0.000 0.000 42.669 42.669 export_plain.py:153(run_re2_test) 1 0.000 0.000 0.000 0.000 {posix.stat} 4 0.000 0.000 0.000 0.000 {time.time} 1 0.000 0.000 0.000 0.000 posixpath.py:59(join) 1 0.000 0.000 42.670 42.670 :1() 1 0.000 0.000 0.000 0.000 {method 'encode' of 'unicode' objects} 3 0.000 0.000 0.000 0.000 {method 'rfind' of 'str' objects} 2 0.000 0.000 0.000 0.000 posixpath.py:109(basename) 1 0.000 0.000 0.000 0.000 posixpath.py:117(dirname) 1 0.000 0.000 0.000 0.000 stat.py:40(S_ISDIR) 2 0.000 0.000 0.000 0.000 {len} 1 0.000 0.000 0.000 0.000 {method 'extend' of 'list' objects} 1 0.000 0.000 0.000 0.000 {method 'startswith' of 'str' objects} 1 0.000 0.000 0.000 0.000 {method 'endswith' of 'str' objects} 1 0.000 0.000 0.000 0.000 stat.py:24(S_IFMT) 1 0.000 0.000 0.000 0.000 {method '__enter__' of 'file' objects} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
It looks like that the _search
function (re2.pyx:393) take up too much time.
But I don't how can be so different between this and the pure C version.
PS:
Pyre2 revision : commit 543f228
re2 revision : changeset: 79:0c439a6bd795
I guess the actual Match
function (re2.pyx:424) cost most of the time in this function.
Then I refactor Match function to a cdef function _my_match
so that I can see it in profile result, also refactor StringPiece
allocation to cdef function _alloc_sp
. (Modification detail: https://gist.github.com/1873993) Re-profile it, then get:
Mon Feb 20 20:52:47 2012 Profile.prof 3975043 function calls in 28.265 CPU seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 652884 10.060 0.000 20.230 0.000 re2.pyx:452(search) 652884 4.131 0.000 28.201 0.000 {method 'search' of 're2.Pattern' objects} 652884 3.647 0.000 3.647 0.000 re2.pyx:394(_my_match) 9479 3.037 0.000 31.238 0.003 export_plain.py:62(match) 652884 2.901 0.000 2.901 0.000 re2.pyx:443(_alloc_sp) 652953 1.814 0.000 1.814 0.000 re2.pyx:86(pystring_to_bytestring) 652953 1.808 0.000 1.808 0.000 re2.pyx:75(unicode_to_bytestring) 1 0.332 0.332 31.926 31.926 export_plain.py:96(export_fname) 9479 0.169 0.000 0.169 0.000 {built-in method sub} 10000 0.122 0.000 0.122 0.000 {method 'split' of 'str' objects} 8967 0.065 0.000 0.099 0.000 re2.pyx:849(get) 10069 0.064 0.000 0.064 0.000 {method 'strip' of 'str' objects} 69 0.042 0.001 0.142 0.002 re2.pyx:854(prepare_pattern) 9036 0.035 0.000 0.035 0.000 re2.pyx:836(__next) 69 0.023 0.000 0.166 0.002 re2.pyx:953(_compile) 1 0.003 0.003 32.103 32.103 export_plain.py:158(main) 1 0.003 0.003 0.174 0.174 export_plain.py:36(load) 69 0.002 0.000 0.168 0.002 re2.pyx:811(compile) 38 0.001 0.000 0.001 0.000 {method 'write' of 'file' objects} 69 0.001 0.000 0.169 0.002 {re2.compile} 69 0.001 0.000 0.001 0.000 re2.pyx:832(__init__) 1 0.001 0.001 32.104 32.104 export_plain.py:151(run_re2_test) 1 0.000 0.000 32.105 32.105 :1() 2 0.000 0.000 0.000 0.000 {len} 3 0.000 0.000 0.000 0.000 {open} 1 0.000 0.000 0.000 0.000 {method 'extend' of 'list' objects} 69 0.000 0.000 0.000 0.000 {isinstance} 69 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects} 19 0.000 0.000 0.000 0.000 {method 'join' of 'str' objects} 4 0.000 0.000 0.000 0.000 {time.time} 1 0.000 0.000 0.000 0.000 {method 'encode' of 'unicode' objects} 1 0.000 0.000 0.000 0.000 posixpath.py:59(join) 1 0.000 0.000 0.000 0.000 {posix.stat} 1 0.000 0.000 0.000 0.000 genericpath.py:38(isdir) 2 0.000 0.000 0.000 0.000 posixpath.py:109(basename) 3 0.000 0.000 0.000 0.000 {method 'rfind' of 'str' objects} 1 0.000 0.000 0.000 0.000 posixpath.py:117(dirname) 1 0.000 0.000 0.000 0.000 stat.py:40(S_ISDIR) 1 0.000 0.000 0.000 0.000 {method 'startswith' of 'str' objects} 1 0.000 0.000 0.000 0.000 {method 'endswith' of 'str' objects} 1 0.000 0.000 0.000 0.000 {method '__enter__' of 'file' objects} 1 0.000 0.000 0.000 0.000 stat.py:24(S_IFMT) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
But search
still take up so much time (10.060 in tottime).
Anyone can figure out what's the problem?