5x startup performance regression from August to December #266

kislyuk · 2017-01-05T01:09:54Z

>cwltool --version
/usr/local/bin/cwltool 1.0.20160829211335
>time cwltool ~/projects/common-workflow-language/v1.0/examples/1st-tool.cwl <(echo '{"message": "test"}')
/usr/local/bin/cwltool 1.0.20160829211335
[job 1st-tool.cwl] /private/var/folders/jd/711qq60d4451bqmp5w88bk800000gn/T/tmpmCSOsK$ echo \
    test
test
Final process status is success
{}

real	0m2.235s
user	0m1.608s
sys	0m0.602s

After upgrading:

>cwltool --version
/usr/local/bin/cwltool 1.0.20161227200419
>time cwltool ~/projects/common-workflow-language/v1.0/examples/1st-tool.cwl <(echo '{"message": "test"}')
/usr/local/bin/cwltool 1.0.20161227200419
Resolved '/Users/kislyuk/projects/common-workflow-language/v1.0/examples/1st-tool.cwl' to 'file:///Users/kislyuk/projects/common-workflow-language/v1.0/examples/1st-tool.cwl'
[job 1st-tool.cwl] /private/var/folders/jd/711qq60d4451bqmp5w88bk800000gn/T/tmpQNAfP_$ echo \
    test
test
Final process status is success
{}

real	0m10.765s
user	0m10.091s
sys	0m0.592s

The text was updated successfully, but these errors were encountered:

kislyuk · 2017-01-05T01:35:39Z

Bisected the regression to the delta between ruamel.yaml==0.13.4 and ruamel.yaml==0.13.5.

tetron · 2017-01-05T14:45:31Z

I noticed it seemed slower but didn't investigate. Are you saying that the same cwltool code with ruamel.yaml==0.13.4 is fine but ruamel.yaml==0.13.5 is much slower?

kislyuk · 2017-01-05T16:18:31Z

Yes, that is what I'm saying. Please take a look at the example above, it should be easy to reproduce.

undu · 2017-01-14T13:37:36Z

Just chiming in to confirm this happens in my linux system.

There's a noticeable time gap (> 5 seconds) between printing
Resolved 'workflow.cwl' to 'file:///home/pau/dev/cwl-test/workflow.cwl'
and starting the first step of the workflow, whereas before it seemed instant.

undu · 2017-01-14T14:07:48Z

Did some profiling to shed more light on the issue:

>>>p.sort_stats('cumulative').print_stats(30)
Sat Jan 14 14:04:16 2017    profile.bin

         35912247 function calls (31646894 primitive calls) in 13.178 seconds

   Ordered by: cumulative time
   List reduced from 2664 to 30 due to restriction <30>

       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            1    0.001    0.001   13.180   13.180 /home/pau/.config/virtualenvs/cwl/bin/cwltool:4(<module>)
            1    0.000    0.000   12.701   12.701 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/cwltool/main.py:548(main)
            2    0.000    0.000   12.214    6.107 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/cwltool/load_tool.py:109(validate_document)
            3    0.001    0.000   12.204    4.068 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/cwltool/process.py:89(get_schema)
            1    0.002    0.002   12.200   12.200 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/schema_salad/schema.py:181(load_schema)
            5    0.002    0.000   11.757    2.351 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/schema_salad/schema.py:511(make_avro_schema)
 3740100/7394    4.018    0.000   11.656    0.002 /usr/lib64/python2.7/copy.py:145(deepcopy)
   19084/4117    0.181    0.000   11.502    0.003 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/comments.py:752(__deepcopy__)
        71993    0.346    0.000   10.895    0.000 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/comments.py:300(copy_attributes)
 289804/71974    0.497    0.000    9.642    0.000 /usr/lib64/python2.7/copy.py:226(_deepcopy_list)
198801/158901    0.706    0.000    9.241    0.000 /usr/lib64/python2.7/copy.py:306(_reconstruct)
            5    0.003    0.001    6.338    1.268 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/schema_salad/schema.py:428(extend_and_specialize)
280432/152982    0.578    0.000    6.130    0.000 /usr/lib64/python2.7/copy.py:253(_deepcopy_dict)
     5160/103    0.022    0.000    5.617    0.055 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/schema_salad/schema.py:331(replace_type)
      2068/11    0.014    0.000    5.398    0.491 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/schema_salad/schema.py:385(make_valid_avro)
319275/239475    0.802    0.000    3.826    0.000 /usr/lib64/python2.7/copy.py:234(_deepcopy_tuple)
      2982885    1.349    0.000    1.722    0.000 /usr/lib64/python2.7/copy.py:267(_keep_alive)
    3245/2721    0.012    0.000    1.473    0.001 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/comments.py:370(__deepcopy__)
            1    0.000    0.000    0.921    0.921 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/schema_salad/schema.py:51(get_metaschema)
       2374/5    0.008    0.000    0.672    0.134 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/schema_salad/ref_resolver.py:681(resolve_all)
        35/11    0.000    0.000    0.662    0.060 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/schema_salad/ref_resolver.py:386(resolve_ref)
           14    0.000    0.000    0.659    0.047 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/main.py:127(round_trip_load)
           14    0.001    0.000    0.659    0.047 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/main.py:73(load)
           14    0.000    0.000    0.657    0.047 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/constructor.py:52(get_single_data)
       198801    0.634    0.000    0.635    0.000 {method '__reduce_ex__' of 'object' objects}
      6973878    0.620    0.000    0.620    0.000 {method 'get' of 'dict' objects}
           14    0.000    0.000    0.606    0.043 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/composer.py:43(get_single_node)
           14    0.000    0.000    0.604    0.043 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/composer.py:65(compose_document)
      3664/14    0.010    0.000    0.604    0.043 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/composer.py:78(compose_node)
       482/22    0.005    0.000    0.593    0.027 /home/pau/.config/virtualenvs/cwl/lib/python2.7/site-packages/ruamel/yaml/composer.py:146(compose_mapping_node)

These are ordered by total time spent in seconds inside a function. (cumtime)

mr-c · 2017-01-16T12:34:56Z

This has been reported to ruaml.yaml's author https://bitbucket.org/ruamel/yaml/issues/87/is-there-a-performance-regression-test-for

tetron · 2017-01-16T15:01:41Z

Perhaps what we need is an option to use safe_load() instead of round_trip_load(). The error reporting will be less helpful, but it won't be burdened of the metadata that is making deep_copy() so expensive. Maybe default to safe_load for schema loading and round_trip_load for user file loading.

tetron · 2017-01-26T18:54:28Z

I have released a new version of schema salad which I believe fixes the performance regression: https://github.com/common-workflow-language/schema_salad/releases/tag/2.2.20170126160727

thanks @kislyuk @undu investigating it. please verify and close the issue if you're satisfied.

undu · 2017-01-30T12:01:41Z

Startup performance is much better now, thanks!

2cf0896 Merge pull request common-workflow-language#289 from denis-yuen/patch-1 68f5f90 Merge pull request common-workflow-language#291 from bmeg/master a82cf0d Merge https://github.com/bmeg/common-workflow-language e7325dc Adding docker hint for conformance test 70501d5 Merge pull request common-workflow-language#290 from alaindomissy/patch-1 58a9354 Update concepts.md 1b052b5 Fix a typo 4a02bc7 Test that expressionLib requirement of individual tool step overrides expressionLib of workflow. 80e2501 add path to record-job3.yaml c9df19c Add checksum to cwl.output.json results. e604399 Add tests that $HOME and $TMPDIR are set correctly according to spec. a479bbd Add checksums and sizes to secondaryFiles in draft-3 tests. dfcbfeb Merge pull request common-workflow-language#286 from common-workflow-language/test-nested-array 91bb7b4 Test case for command line generation of array-of-arrays. 5baf924 Merge pull request common-workflow-language#285 from common-workflow-language/checksum-secondary 1c02570 Merge pull request common-workflow-language#282 from common-workflow-language/test-inputbinding-dir 1835540 Add checksums to secondaryFiles and files in Directory objects. 04d9dac Add test for command line inputBinding of Directory input parameter. 8053c4b Merge pull request common-workflow-language#279 from simonovic86/patch-1 168d1a2 Update README.md e727a46 Merge pull request common-workflow-language#277 from common-workflow-language/add-biostars-link bfddadc fix typo 9ec9642 add biostars link b67a4cf Merge pull request common-workflow-language#272 from StarvingMarvin/master 570ae5f Merge pull request common-workflow-language#266 from common-workflow-language/remove-empty-baseCommand 721ffdc Merge remote-tracking branch 'origin/master' into remove-empty-baseCommand 6931eeb minor userguide fixes a296c5f Remove "baseCommand: []" from tests. git-subtree-dir: cwltool/schemas git-subtree-split: 2cf0896

…seCommand Remove empty base command

tetron closed this as completed Jan 30, 2017

tetron pushed a commit that referenced this issue Jul 23, 2017

Merge pull request #266 from common-workflow-language/remove-empty-ba…

570ae5f

…seCommand Remove empty base command

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

5x startup performance regression from August to December #266

5x startup performance regression from August to December #266

kislyuk commented Jan 5, 2017

kislyuk commented Jan 5, 2017

tetron commented Jan 5, 2017

kislyuk commented Jan 5, 2017

undu commented Jan 14, 2017

undu commented Jan 14, 2017 •

edited

mr-c commented Jan 16, 2017

tetron commented Jan 16, 2017

tetron commented Jan 26, 2017

undu commented Jan 30, 2017

5x startup performance regression from August to December #266

5x startup performance regression from August to December #266

Comments

kislyuk commented Jan 5, 2017

kislyuk commented Jan 5, 2017

tetron commented Jan 5, 2017

kislyuk commented Jan 5, 2017

undu commented Jan 14, 2017

undu commented Jan 14, 2017 • edited

mr-c commented Jan 16, 2017

tetron commented Jan 16, 2017

tetron commented Jan 26, 2017

undu commented Jan 30, 2017

undu commented Jan 14, 2017 •

edited