New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"import OpenSSL" is 150x slower in 0.14 #137

Closed
kmike opened this Issue Jul 3, 2014 · 21 comments

Comments

Projects
None yet
10 participants
@kmike

kmike commented Jul 3, 2014

Hi,

With latest released pyopenssl, cryptography and cffi "import OpenSSL" takes about 0.5s on a modern i7 CPU with SSD (OS X):

In [1]: %time import OpenSSL
CPU times: user 496 ms, sys: 19.7 ms, total: 516 ms
Wall time: 511 ms

It used to be much faster in pyOpenSSL 0.13.1:

In [1]: %time import OpenSSL
CPU times: user 1.45 ms, sys: 1.81 ms, total: 3.26 ms

Twisted uses OpenSSL, so 0.5s is a startup delay that every Twisted-based software started to pay. It is quite noticable for command-line tools (e.g. Scrapy command line script).

The main contributor to this is cryptography's build_ffi function which uses cffi. I'm not sure how to fix that.

@lvh

This comment has been minimized.

Show comment
Hide comment
@lvh

lvh Jul 3, 2014

Member

Whoa! That's a pretty big difference.

Sounds like importing OpenSSL shouldn't have such a major side effect. Maybe we could have a lazy FFI object that only builds the FFI the first time anything actually tries to access it? It may be a good idea to invoke clever FFI folks (paging @alex) for an opinion :)

Member

lvh commented Jul 3, 2014

Whoa! That's a pretty big difference.

Sounds like importing OpenSSL shouldn't have such a major side effect. Maybe we could have a lazy FFI object that only builds the FFI the first time anything actually tries to access it? It may be a good idea to invoke clever FFI folks (paging @alex) for an opinion :)

@public

This comment has been minimized.

Show comment
Hide comment
@public

public Jul 3, 2014

Member

I think cffi are making some changes that will improve this behaviour but it might be a while until we can use those :-/ We could do a lazy backend object but I kind of imagine it won't defer the slowness for very long in a lot of cases? There's also the question of when you'd rather pay that 0.5s cost? e.g. At the first TCP connection you make, or at import time?

Member

public commented Jul 3, 2014

I think cffi are making some changes that will improve this behaviour but it might be a while until we can use those :-/ We could do a lazy backend object but I kind of imagine it won't defer the slowness for very long in a lot of cases? There's also the question of when you'd rather pay that 0.5s cost? e.g. At the first TCP connection you make, or at import time?

@lvh

This comment has been minimized.

Show comment
Hide comment
@lvh

lvh Jul 3, 2014

Member

I'm hoping that that would happen just a little sooner than the first connection, but that still sounds better than "unconditionally on import".

(I was thinking about Contexts and ContextFactories, but I suppose that you still don't actually call any OpenSSL APIs... I guess whoever figures that out should go read the implementation for SSL4Endpoint? :))

Member

lvh commented Jul 3, 2014

I'm hoping that that would happen just a little sooner than the first connection, but that still sounds better than "unconditionally on import".

(I was thinking about Contexts and ContextFactories, but I suppose that you still don't actually call any OpenSSL APIs... I guess whoever figures that out should go read the implementation for SSL4Endpoint? :))

@exarkun

This comment has been minimized.

Show comment
Hide comment
@exarkun

exarkun Jul 3, 2014

Member

The main contributor to this is cryptography's build_ffi function which uses cffi. I'm not sure how to fix that.

It would be good if you could share how you came to this conclusion.

Member

exarkun commented Jul 3, 2014

The main contributor to this is cryptography's build_ffi function which uses cffi. I'm not sure how to fix that.

It would be good if you could share how you came to this conclusion.

@kmike

This comment has been minimized.

Show comment
Hide comment
@kmike

kmike Jul 3, 2014

@exarkun I've executed

python -m cProfile -o scrapy.prof `which scrapy`

and used RunSnakeRun to check the results. The highlighted box on the left represents pyOpenSSL import (relative size looks wrong btw); started from pink is cryptography and cffi overhead.
screen shot 2014-07-03 at 5 02 30 pm

A more direct way is to run

In [1]: %prun -s cumtime import OpenSSL

from IPython; this gives the following result:

         848745 function calls (830804 primitive calls) in 0.697 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    0.697    0.697 __init__.py:6(<module>)
        1    0.001    0.001    0.695    0.695 rand.py:5(<module>)
        1    0.001    0.001    0.693    0.693 _util.py:1(<module>)
        1    0.000    0.000    0.691    0.691 binding.py:86(__init__)
        1    0.000    0.000    0.691    0.691 binding.py:89(_ensure_ffi_initialized)
        1    0.000    0.000    0.691    0.691 utils.py:23(build_ffi)
        1    0.000    0.000    0.641    0.641 api.py:91(cdef)
        1    0.000    0.000    0.641    0.641 cparser.py:151(parse)
        1    0.001    0.001    0.641    0.641 cparser.py:162(_internal_parse)
        1    0.000    0.000    0.574    0.574 cparser.py:103(_parse)
        1    0.000    0.000    0.531    0.531 c_parser.py:118(parse)
        1    0.000    0.000    0.531    0.531 yacc.py:257(parse)
        1    0.171    0.171    0.531    0.531 yacc.py:869(parseopt_notrack)
    14022    0.011    0.000    0.148    0.000 c_lexer.py:76(token)
    14022    0.072    0.000    0.137    0.000 lex.py:304(token)
     1450    0.004    0.000    0.063    0.000 cparser.py:200(_parse_decl)
6304/1517    0.024    0.000    0.052    0.000 cparser.py:255(_get_type)
    50431    0.044    0.000    0.044    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
  919/893    0.006    0.000    0.042    0.000 cparser.py:338(_parse_function_type)
        1    0.000    0.000    0.038    0.038 api.py:329(verify)
        1    0.000    0.000    0.037    0.037 verifier.py:61(load_library)
        1    0.000    0.000    0.032    0.032 cparser.py:28(_get_parser)
        1    0.000    0.000    0.032    0.032 c_parser.py:20(__init__)
     1560    0.004    0.000    0.029    0.000 c_parser.py:599(p_decl_body)
       16    0.000    0.000    0.026    0.002 re.py:194(compile)
       16    0.000    0.000    0.026    0.002 re.py:232(_compile)
     1912    0.008    0.000    0.026    0.000 c_parser.py:1082(p_parameter_declaration_2)
       16    0.000    0.000    0.026    0.002 sre_compile.py:496(compile)
     1702    0.012    0.000    0.026    0.000 c_parser.py:357(_build_declarations)
        1    0.000    0.000    0.024    0.024 c_lexer.py:58(build)
        1    0.000    0.000    0.024    0.024 lex.py:865(lex)
        1    0.000    0.000    0.023    0.023 lex.py:214(readtab)
        1    0.000    0.000    0.019    0.019 verifier.py:149(_load_library)
        1    0.000    0.000    0.019    0.019 vengine_cpy.py:130(load_library)
        1    0.000    0.000    0.018    0.018 verifier.py:102(_locate_module)
        1    0.000    0.000    0.018    0.018 vengine_cpy.py:32(collect_types)
        1    0.002    0.002    0.018    0.018 vengine_cpy.py:180(_generate)

kmike commented Jul 3, 2014

@exarkun I've executed

python -m cProfile -o scrapy.prof `which scrapy`

and used RunSnakeRun to check the results. The highlighted box on the left represents pyOpenSSL import (relative size looks wrong btw); started from pink is cryptography and cffi overhead.
screen shot 2014-07-03 at 5 02 30 pm

A more direct way is to run

In [1]: %prun -s cumtime import OpenSSL

from IPython; this gives the following result:

         848745 function calls (830804 primitive calls) in 0.697 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    0.697    0.697 __init__.py:6(<module>)
        1    0.001    0.001    0.695    0.695 rand.py:5(<module>)
        1    0.001    0.001    0.693    0.693 _util.py:1(<module>)
        1    0.000    0.000    0.691    0.691 binding.py:86(__init__)
        1    0.000    0.000    0.691    0.691 binding.py:89(_ensure_ffi_initialized)
        1    0.000    0.000    0.691    0.691 utils.py:23(build_ffi)
        1    0.000    0.000    0.641    0.641 api.py:91(cdef)
        1    0.000    0.000    0.641    0.641 cparser.py:151(parse)
        1    0.001    0.001    0.641    0.641 cparser.py:162(_internal_parse)
        1    0.000    0.000    0.574    0.574 cparser.py:103(_parse)
        1    0.000    0.000    0.531    0.531 c_parser.py:118(parse)
        1    0.000    0.000    0.531    0.531 yacc.py:257(parse)
        1    0.171    0.171    0.531    0.531 yacc.py:869(parseopt_notrack)
    14022    0.011    0.000    0.148    0.000 c_lexer.py:76(token)
    14022    0.072    0.000    0.137    0.000 lex.py:304(token)
     1450    0.004    0.000    0.063    0.000 cparser.py:200(_parse_decl)
6304/1517    0.024    0.000    0.052    0.000 cparser.py:255(_get_type)
    50431    0.044    0.000    0.044    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
  919/893    0.006    0.000    0.042    0.000 cparser.py:338(_parse_function_type)
        1    0.000    0.000    0.038    0.038 api.py:329(verify)
        1    0.000    0.000    0.037    0.037 verifier.py:61(load_library)
        1    0.000    0.000    0.032    0.032 cparser.py:28(_get_parser)
        1    0.000    0.000    0.032    0.032 c_parser.py:20(__init__)
     1560    0.004    0.000    0.029    0.000 c_parser.py:599(p_decl_body)
       16    0.000    0.000    0.026    0.002 re.py:194(compile)
       16    0.000    0.000    0.026    0.002 re.py:232(_compile)
     1912    0.008    0.000    0.026    0.000 c_parser.py:1082(p_parameter_declaration_2)
       16    0.000    0.000    0.026    0.002 sre_compile.py:496(compile)
     1702    0.012    0.000    0.026    0.000 c_parser.py:357(_build_declarations)
        1    0.000    0.000    0.024    0.024 c_lexer.py:58(build)
        1    0.000    0.000    0.024    0.024 lex.py:865(lex)
        1    0.000    0.000    0.023    0.023 lex.py:214(readtab)
        1    0.000    0.000    0.019    0.019 verifier.py:149(_load_library)
        1    0.000    0.000    0.019    0.019 vengine_cpy.py:130(load_library)
        1    0.000    0.000    0.018    0.018 verifier.py:102(_locate_module)
        1    0.000    0.000    0.018    0.018 vengine_cpy.py:32(collect_types)
        1    0.002    0.002    0.018    0.018 vengine_cpy.py:180(_generate)

@hynek

This comment has been minimized.

Show comment
Hide comment
@hynek

hynek Oct 17, 2014

Contributor

I’ve just had lunch with @fijal and @arigo and they confirmed that they work on separating “building” and “using” cffi modules so this will hopefully solve this problem.

Contributor

hynek commented Oct 17, 2014

I’ve just had lunch with @fijal and @arigo and they confirmed that they work on separating “building” and “using” cffi modules so this will hopefully solve this problem.

@erydo

This comment has been minimized.

Show comment
Hide comment
@erydo

erydo Dec 13, 2014

I really appreciate this package since it enables us to use SNI on our python2.7 codebase, however I'm seeing about a 21+ second import time in 0.14 on a Raspberry Pi which is a major constraint for the time being. @fijal, @arigo, @hynek — Have you been able to make much progress on the mentioned refactor, and is there a PR we might be able to look at, help test, or contribute to?

erydo commented Dec 13, 2014

I really appreciate this package since it enables us to use SNI on our python2.7 codebase, however I'm seeing about a 21+ second import time in 0.14 on a Raspberry Pi which is a major constraint for the time being. @fijal, @arigo, @hynek — Have you been able to make much progress on the mentioned refactor, and is there a PR we might be able to look at, help test, or contribute to?

@alex

This comment has been minimized.

Show comment
Hide comment
@alex

alex Dec 13, 2014

Member

So, cffi 1.0 is in progress, and it will completely remove the import time
overhead.

In the meantime, if your primary goal is getting SNI support, I'd encourage
you to upgrade your Python to 2.7.9, where the stdlib includes SNI support,
and then you can just avoid the extra dependency.

On Sat Dec 13 2014 at 11:59:42 AM Robert Estelle notifications@github.com
wrote:

I really appreciate this package since it enables us to use SNI on our
python2.7 codebase, however I'm seeing about a 21+ second import time in
0.14 on a Raspberry Pi which is a major constraint for the time being.
@fijal https://github.com/fijal, @arigo https://github.com/arigo,
@hynek https://github.com/hynek — Have you been able to make much
progress on the mentioned refactor, and is there a PR we might be able to
look at, help test, or contribute to?


Reply to this email directly or view it on GitHub
#137 (comment).

Member

alex commented Dec 13, 2014

So, cffi 1.0 is in progress, and it will completely remove the import time
overhead.

In the meantime, if your primary goal is getting SNI support, I'd encourage
you to upgrade your Python to 2.7.9, where the stdlib includes SNI support,
and then you can just avoid the extra dependency.

On Sat Dec 13 2014 at 11:59:42 AM Robert Estelle notifications@github.com
wrote:

I really appreciate this package since it enables us to use SNI on our
python2.7 codebase, however I'm seeing about a 21+ second import time in
0.14 on a Raspberry Pi which is a major constraint for the time being.
@fijal https://github.com/fijal, @arigo https://github.com/arigo,
@hynek https://github.com/hynek — Have you been able to make much
progress on the mentioned refactor, and is there a PR we might be able to
look at, help test, or contribute to?


Reply to this email directly or view it on GitHub
#137 (comment).

@erydo

This comment has been minimized.

Show comment
Hide comment
@erydo

erydo Dec 13, 2014

@alex Wow, Python 2.7.9 was released just this week. That's perfect timing. Thank you so much for pointing that out, I'll look into it.

erydo commented Dec 13, 2014

@alex Wow, Python 2.7.9 was released just this week. That's perfect timing. Thank you so much for pointing that out, I'll look into it.

@rabbbit

This comment has been minimized.

Show comment
Hide comment
@rabbbit

rabbbit Jun 8, 2015

cffi is currently at 1.1.1 and the import overhead is still present. I guess upgrading to 2.7.10 is the way :)

rabbbit commented Jun 8, 2015

cffi is currently at 1.1.1 and the import overhead is still present. I guess upgrading to 2.7.10 is the way :)

@hynek

This comment has been minimized.

Show comment
Hide comment
@hynek

hynek Jun 8, 2015

Contributor

The overhead won't go magically away. We need a cryptography release with pyca/cryptography#1986 first.

Contributor

hynek commented Jun 8, 2015

The overhead won't go magically away. We need a cryptography release with pyca/cryptography#1986 first.

@reaperhulk

This comment has been minimized.

Show comment
Hide comment
@reaperhulk

reaperhulk Jun 9, 2015

Member

@rabbbit if you build cryptography against current master you should see the import overhead disappear. We don't currently have a timeline for our next release, but history suggests it will be within the next 4 weeks.

Member

reaperhulk commented Jun 9, 2015

@rabbbit if you build cryptography against current master you should see the import overhead disappear. We don't currently have a timeline for our next release, but history suggests it will be within the next 4 weeks.

@rabbbit

This comment has been minimized.

Show comment
Hide comment
@rabbbit

rabbbit Jun 9, 2015

Thank you :)

rabbbit commented Jun 9, 2015

Thank you :)

@dhermes

This comment has been minimized.

Show comment
Hide comment
@dhermes

dhermes Jun 9, 2015

@reaperhulk Do you guys have a release announce list?

dhermes commented Jun 9, 2015

@reaperhulk Do you guys have a release announce list?

@reaperhulk

This comment has been minimized.

Show comment
Hide comment
@reaperhulk

reaperhulk Jun 9, 2015

Member

We have a generic cryptography-dev list that we do announcements on, but we also CC release announcements to python-announce

Member

reaperhulk commented Jun 9, 2015

We have a generic cryptography-dev list that we do announcements on, but we also CC release announcements to python-announce

@dhermes

This comment has been minimized.

Show comment
Hide comment
@dhermes

dhermes commented Jun 9, 2015

Thanks

@dhermes

This comment has been minimized.

Show comment
Hide comment
@dhermes

dhermes Jul 6, 2015

w00t, cryptography 0.9.2 was released July 3

dhermes commented Jul 6, 2015

w00t, cryptography 0.9.2 was released July 3

@reaperhulk

This comment has been minimized.

Show comment
Hide comment
@reaperhulk

reaperhulk Jul 6, 2015

Member

@dhermes 0.9.2 won't fix this issue unfortunately. You'll have to wait for 1.0 for that. That will hopefully be in the next 2 weeks

Member

reaperhulk commented Jul 6, 2015

@dhermes 0.9.2 won't fix this issue unfortunately. You'll have to wait for 1.0 for that. That will hopefully be in the next 2 weeks

@dhermes

This comment has been minimized.

Show comment
Hide comment
@dhermes

dhermes Jul 6, 2015

Thanks for the update

dhermes commented Jul 6, 2015

Thanks for the update

@reaperhulk

This comment has been minimized.

Show comment
Hide comment
@reaperhulk

reaperhulk Aug 13, 2015

Member

1.0 has resolved this issue :) (but created that pypy issue for you, sorry @dhermes!)

Member

reaperhulk commented Aug 13, 2015

1.0 has resolved this issue :) (but created that pypy issue for you, sorry @dhermes!)

@reaperhulk reaperhulk closed this Aug 13, 2015

@kmike

This comment has been minimized.

Show comment
Hide comment
@kmike

kmike commented Aug 13, 2015

\o/

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment