#6690 Plugin schema cache is slow
Closed: fixed 7 years ago Opened 7 years ago by cheimes.

The schema cache for remote plugins is slow and reduces startup performance of ipa CLI considerable. A simple 'ipa ping' spends 244ms out of of 746ms in just reading from the zipped schema file. This doesn't include JSON deserialization.

Considering the performance issue and other issues like #6668, we might want to look into other options. For example sqlite with gzipped Python pickles (protocol v2) blobs should be faster than JSON and zip.

$ PYTHONPATH=$(pwd) python -m cProfile -o ipa.prof ./ipa ping
$ python
>>> import pstats
>>> p = pstats.Stats('ipa.prof')
>>> p.sort_stats('tottime')
<pstats.Stats instance at 0x7f6af385eab8>
>>> p.print_stats(30)
Mon Feb 20 08:32:14 2017    ipa.prof

         919051 function calls (912320 primitive calls) in 0.746 seconds

   Ordered by: internal time
   List reduced from 3665 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       60    0.142    0.002    0.244    0.004 /usr/lib64/python2.7/zipfile.py:805(_RealGetContents)
        1    0.064    0.064    0.068    0.068 /usr/lib/python2.7/site-packages/idna/idnadata.py:3(<module>)
    36420    0.042    0.000    0.052    0.000 /usr/lib64/python2.7/zipfile.py:287(__init__)
       17    0.027    0.002    0.027    0.002 {method 'readline' of 'nss.io.Socket' objects}
        1    0.019    0.019    0.019    0.019 /usr/lib64/python2.7/socket.py:45(<module>)
   145689    0.016    0.000    0.016    0.000 {method 'read' of 'cStringIO.StringI' objects}
  853/163    0.013    0.000    0.037    0.000 /usr/lib64/python2.7/sre_parse.py:395(_parse)
    36420    0.011    0.000    0.013    0.000 /usr/lib64/python2.7/zipfile.py:383(_decodeExtra)
    17775    0.010    0.000    0.012    0.000 /usr/lib64/python2.7/sre_parse.py:193(__next)
        9    0.009    0.001    0.009    0.001 {posix.read}
    36651    0.009    0.000    0.009    0.000 {_struct.unpack}
       32    0.009    0.000    0.011    0.000 /usr/lib64/python2.7/collections.py:305(namedtuple)
     1002    0.008    0.000    0.021    0.000 /usr/lib/python2.7/site-packages/pkg_resources/_vendor/packaging/version.py:198(__init__)
        1    0.008    0.008    0.008    0.008 {method 'sendall' of 'nss.io.Socket' objects}
128253/127443    0.007    0.000    0.007    0.000 {len}
 1585/150    0.007    0.000    0.017    0.000 /usr/lib64/python2.7/sre_compile.py:64(_compile)
    36459    0.006    0.000    0.006    0.000 {method 'find' of 'str' objects}
    36420    0.006    0.000    0.006    0.000 /usr/lib64/python2.7/zipfile.py:377(_decodeFilename)
      319    0.006    0.000    0.006    0.000 {method 'items' of 'dict' objects}
        1    0.005    0.005    0.006    0.006 /usr/lib64/python2.7/site-packages/cryptography/hazmat/primitives/hashes.py:5(<module>)
      655    0.005    0.000    0.005    0.000 {imp.find_module}
     1002    0.005    0.000    0.005    0.000 /usr/lib/python2.7/site-packages/pkg_resources/_vendor/packaging/version.py:343(_cmpkey)
    67915    0.005    0.000    0.005    0.000 {method 'append' of 'list' objects}
       59    0.004    0.000    0.251    0.004 ./ipaclient/remote_plugins/schema.py:527(read_namespace_member)
    15881    0.004    0.000    0.015    0.000 /usr/lib64/python2.7/sre_parse.py:212(get)
        5    0.004    0.001    0.004    0.001 {posix.fork}
    38289    0.004    0.000    0.004    0.000 {chr}
       66    0.004    0.000    0.009    0.000 ./ipalib/parameters.py:441(__init__)
     2831    0.004    0.000    0.004    0.000 {range}
     1257    0.004    0.000    0.004    0.000 {posix.stat}
>>> p.print_callers('zipfile.py:805')
   Ordered by: internal time
   List reduced from 3665 to 1 due to restriction <'zipfile.py:805'>

Function                                               was called by...
                                                           ncalls  tottime  cumtime
/usr/lib64/python2.7/zipfile.py:805(_RealGetContents)  <-      60    0.142    0.244  /usr/lib64/python2.7/zipfile.py:726(__init__)


<pstats.Stats instance at 0x7f6af385eab8>
>>> p.print_callers('zipfile.py:726')
   Ordered by: internal time
   List reduced from 3665 to 1 due to restriction <'zipfile.py:726'>

Function                                       was called by...
                                                   ncalls  tottime  cumtime
/usr/lib64/python2.7/zipfile.py:726(__init__)  <-       1    0.000    0.004  ./ipaclient/remote_plugins/schema.py:456(_read_schema)
                                                       59    0.000    0.240  ./ipaclient/remote_plugins/schema.py:523(_read)


<pstats.Stats instance at 0x7f6af385eab8>

PR #448 reduces CLI startup time by 25 to 30%.

Metadata Update from @cheimes:
- Issue assigned to cheimes
- Issue set to the milestone: 0.0 NEEDS_TRIAGE

7 years ago

https://github.com/freeipa/freeipa/pull/488

master:
* 332dbab Speed up client schema cache
* 3be696c Drop in-memory copy of schema zip file

Metadata Update from @cheimes:
- Custom field affects_doc reset
- Custom field component reset
- Custom field keywords reset
- Custom field on_review reset
- Custom field type reset
- Issue close_status updated to: None
- Issue set to the milestone: None (was: 0.0 NEEDS_TRIAGE)

7 years ago

Metadata Update from @cheimes:
- Custom field affects_doc reset
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

7 years ago

Metadata Update from @pvoborni:
- Custom field affects_doc reset
- Custom field tester adjusted to wanted
- Issue set to the milestone: FreeIPA 4.5

7 years ago

Login to comment on this ticket.

Metadata