[Python-modules-team] Bug#772506: time spent in ffi (via OpenSSL)

[David Douard]

After a bit more investigation, the culprit is OpenSSL, in which there is the following code 
(in _utils.py which is imported from OpenSSL/__init__.py):

  
  from cryptography.hazmat.bindings.openssl.binding import Binding
  binding = Binding()

and this later Binding() instanciation is the one that takes almost 700ms.


And if we step forward, running:

  import cProfile
  cProfile.run('import OpenSSL', "OSSLstats")
  import pstats
  p=pstats.Stats('OSSLstats')
  p.sort_stats('cumulative').print_stats(20)

  Sun Dec  7 23:37:08 2014    OSSLstats

         982856 function calls (963898 primitive calls) in 0.927 seconds

   Ordered by: cumulative time
   List reduced from 655 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.927    0.927 <string>:1(<module>)
        1    0.001    0.001    0.927    0.927 __init__.py:6(<module>)
        1    0.001    0.001    0.925    0.925 rand.py:5(<module>)
        1    0.001    0.001    0.922    0.922 _util.py:1(<module>)
        1    0.000    0.000    0.920    0.920 binding.py:88(__init__)
        1    0.000    0.000    0.920    0.920 binding.py:91(_ensure_ffi_initialized)
        1    0.000    0.000    0.920    0.920 utils.py:23(build_ffi)
        1    0.000    0.000    0.862    0.862 api.py:90(cdef)
        1    0.000    0.000    0.862    0.862 cparser.py:160(parse)
        1    0.002    0.002    0.862    0.862 cparser.py:171(_internal_parse)
        1    0.000    0.000    0.788    0.788 cparser.py:105(_parse)
        1    0.000    0.000    0.747    0.747 c_parser.py:118(parse)
        1    0.000    0.000    0.747    0.747 yacc.py:261(parse)
        1    0.218    0.218    0.747    0.747 yacc.py:873(parseopt_notrack)
    15098    0.012    0.000    0.179    0.000 c_lexer.py:76(token)
    15098    0.073    0.000    0.167    0.000 lex.py:311(token)
     1603    0.005    0.000    0.069    0.000 cparser.py:238(_parse_decl)
    54251    0.065    0.000    0.065    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
     2074    0.046    0.000    0.058    0.000 c_parser.py:1035(p_pointer)
    72896    0.038    0.000    0.058    0.000 yacc.py:197(__getitem__)


So the time is spent by the _ensure_ffi_initialized class method (of the Binding class) which 
ends up by calling parseopt_notrack which is the slow stuff.

It seems that the time is spent parsing C code when executing  

  ffi.cdef("\n".join(cdef_sources)) (in cryptography/hazmat/bindings/utils.py +57)




-- 

David DOUARD		 LOGILAB
Directeur du département Outils & Systèmes

+33 1 45 32 03 12	 david.douard at logilab.fr
+33 1 83 64 25 26	 http://www.logilab.fr/id/david.douard

Formations - http://www.logilab.fr/formations
Développements - http://www.logilab.fr/services
Gestion de connaissances - http://www.cubicweb.org/
-------------- next part --------------
A non-text attachment was scrubbed...
Name: david_douard.vcf
Type: text/x-vcard
Size: 302 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/python-modules-team/attachments/20141208/00ac0239/attachment.vcf>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 181 bytes
Desc: OpenPGP digital signature
URL: <http://lists.alioth.debian.org/pipermail/python-modules-team/attachments/20141208/00ac0239/attachment.sig>