Improve CLI runtime? #3835

shorowit · 2020-01-07T21:12:41Z

The CLI runtime takes ~1.5 seconds to run on Windows and ~1 second to run on Linux, using this command:
openstudio --no-ssl -e "puts 'hello'"

Without the --no-ssl argument, it's ~2.5 seconds on Windows (Linux is unchanged, still ~1 second).

In some of our residential workflows on Windows, we have to call the CLI twice sequentially, which results in ~3 seconds of runtime for the CLI out of a total workflow runtime of ~10 seconds (which includes applying OS measures and running EnergyPlus). This is a significant percentage. We are trying very hard to reduce our workflow runtime as much as possible.

Can we profile the CLI to look for any obvious performance hot spots?

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

tijcolem · 2020-01-10T17:35:06Z

This might be due to grepping for the ruby gems on startup. We may be able to change this behavior and not look at the gems on load.

shorowit · 2020-03-09T20:08:03Z

Just tried the latest v3.0 beta build (OpenStudio-3.0.0-beta+644272d34e) and I'm seeing similar times on Windows (roughly 1.5 seconds).

@joseph-robertson

joseph-robertson · 2020-03-17T19:06:00Z

@kbenne suggested that I try commenting out these init statements: https://github.com/NREL/OpenStudio/blob/develop/src/cli/main.cpp#L221

Here's what happens when I comment out the first one and rebuild:

$ time ./OpenStudio/build/Products/Release/openstudio.exe -e "puts 'hello'"

Error: BINARY is not ASCII compatible
Backtrace:
        :/ruby/2.5.0/openssl/buffering.rb:1
        eval:137:in `eval'
        eval:137:in `require_embedded_absolute'
        eval:110:in `block in require'
        eval:104:in `each'
        eval:104:in `require'
        :/ruby/2.5.0/openssl/ssl.rb:13:in `<main>'
        eval:137:in `eval'
        eval:137:in `require_embedded_absolute'
        eval:110:in `block in require'
        eval:104:in `each'
        eval:104:in `require'
        :/ruby/2.5.0/openssl.rb:21:in `<main>'
        eval:137:in `eval'
        eval:137:in `require_embedded_absolute'
        eval:110:in `block in require'
        eval:104:in `each'
        eval:104:in `require'
        :/ruby/2.5.0/rubygems/security.rb:12:in `<main>'
        eval:137:in `eval'
        eval:137:in `require_embedded_absolute'
        eval:110:in `block in require'
        eval:104:in `each'
        eval:104:in `require'
        :/ruby/2.5.0/rubygems/package.rb:44:in `<main>'
        eval:137:in `eval'
        eval:137:in `require_embedded_absolute'
        eval:110:in `block in require'
        eval:104:in `each'
        eval:104:in `require'
        :/ruby/2.5.0/rubygems/installer.rb:10:in `<main>'
        eval:137:in `eval'
        eval:137:in `require_embedded_absolute'
        eval:110:in `block in require'
        eval:104:in `each'
        eval:104:in `require'
        :/ruby/2.5.0/rubygems.rb:1357:in `<module:Gem>'
        :/ruby/2.5.0/rubygems.rb:117:in `<main>'
        eval:137:in `eval'
        eval:137:in `require_embedded_absolute'
        eval:110:in `block in require'
        eval:104:in `each'
        eval:104:in `require'
        :/openstudio_cli.rb:68:in `<main>'
        eval:137:in `eval'
        eval:137:in `require_embedded_absolute'
        eval:110:in `block in require'
        eval:104:in `each'
        eval:104:in `require'
        eval:3:in `<main>'
Exception: BINARY is not ASCII compatible
ruby: unexpected return

real    0m2.075s
user    0m0.000s
sys     0m0.093s

joseph-robertson · 2020-03-30T21:03:19Z

So, commenting out the Init_* statements results in error (see above). I also tried commenting out the rb_provide(...) lines. It builds successfully. The cli call runs in ~0.5 seconds but the output is missing (probably some kind of silent fail).

@kbenne Any other ideas?

joseph-robertson · 2020-03-30T22:01:02Z

I timed how long it takes to get through all the Init_* and rb_provide(...) lines. It doesn't appear to be too much time:

$ ./build/Products/Release/openstudio.exe -e "puts 'hello'"
Elapsed time: 0.023413 s
hello

joseph-robertson · 2020-03-31T19:41:48Z

$ time ./build/Products/Release/openstudio.exe -e "puts 'hello'"
ruby_sysinit: 0.0323461 s
Init and rb_provide 1: 0.0398413 s
Init and rb_provide 2: 0 s
init_openstudio_internal inits: 0.349156 s
ruby_typedef_script: 0.0005962 s
init_openstudio_internal: 0.374873 s
openstudio_cli.rb:
        require 'openstudio': 1.9e-05 s
        require 'logger', 'optparse', 'stringio', 'rbconfig': 0.019641 s
        require 'rubygems', 'rubygems/version': 0.481018 s
        require Gem::Platform.local: 4.0e-05 s
        split_main_and_subcommand: 4.9e-05 s
        parse_main_args:
                main_args loop 1: 2.7e-05 s
                main_args loop 2: 4.0e-06 s
                main_args includes: 5.0e-05 s
                Gem.paths.path: 0.000499 s
                original_embedded_gems: 0.354363 s
                Gem::Specification: 0.00068 s
                if use_bundler: 0.024457 s
                rest of parse_main_args: 7.0e-06 s
        parse_main_args: 0.382809 s
hello
require openstudio_cli: 0.896727 s
after require openstudio_cli: 2.16e-05 s

real    0m1.525s
user    0m0.015s
sys     0m0.046s

Large factors:

init_openstudio_internal
require 'rubygems', 'rubygems/version'
original_embedded_gems

@kbenne suggested to:

avoid require 'rubygems' if not using bundle (might not be completely possible though because of baked in gems)
rewrite / optimize original_embedded_gems

tijcolem · 2020-07-10T14:21:50Z

@lefticus I assigned this to you and sent you another email with a few more details concerning this.

lefticus · 2020-07-18T18:22:16Z

Current no-op run time for me, for reference, with Release build (this is consistent across multiple runs)

Linux -O3 -g to enable debug symbols for better performance tracking

Addresses #3835

lefticus · 2020-07-18T19:13:16Z

After a478258 time on my Linux box is:

lefticus · 2020-07-18T21:49:03Z

Windows best of 10 runs:
1.457 before changes
1.047 after changes

29% faster for Windows, 35% Linux

lefticus · 2020-07-19T01:28:13Z

Tested with LTO - no difference in load times (but much smaller memory footprint possible)

The remaining work is mostly internal to SWIG and Ruby, and it is the registration of the 10's of thousands of functions we have.

It is theoretically possible to set up lazy loading of the OpenStudio modules (everything after OpenStudio core/utilities). But it does not seem to me this would make any practical difference.

That is, any meaningful use of openstudio_cli is going to want OpenStudioModel, which is by far the largest part of OpenStudio. If we lazy load OpenStudioModel, but it's always needed, then nothing has been gained.

Re: @tijcolem @joseph-robertson

Is the current ~30% improvement good? Do you think lazy loading of OpenStudioModel would have practical benefit?

kbenne · 2020-07-20T15:13:59Z

@lefticus do you have evidence from the profiler that most of the init time is related to OpenStudioModel? We are also initing a lot of extensions from the ruby standard library as well as a number of gems. I'm not disagreeing that Model is probably the biggest culprit, but it might be wise to quantify our suspicions.

lefticus · 2020-07-20T21:17:46Z

Yes, if I disable the model only the times go all the way down to something like .28s. It's by far the bulk of the work (and the profiler agrees).

The reason you were seeing the load times increase for more embedded gems came down the all of the file string copies increasing as well.

shorowit · 2020-07-20T21:27:40Z

@lefticus Are you running it with the -e argument? I.e., openstudio -e "puts 'hello'"?

I feel like @joseph-robertson looked at this at one point and found a fairly significant amount of time spent in the ruby gem handling code. Not sure if he still has the numbers.

kbenne · 2020-07-20T21:33:44Z

If we take @lefticus data as truth. Are there use cases that would justify selectively disabling the the OpenStudio Model with a cli flag? Can we lazy load the model?

kbenne · 2020-07-20T22:00:04Z

what am I saying of course we can lazy the load openstudio. We have reimplemented require and within that implementation we could if require_path == openstudio then initOpenStudio but should we? I wonder if there are people out there using the openstudio cli, using OpenStudio api, but omitting require 'openstudio'. Certainly they could be doing that as the code is written today.

shorowit · 2020-07-20T22:04:34Z

This is really interesting. I just realized that we have situations where we use the OpenStudio CLI but don't do anything with the OS Model. We basically just use the CLI as a ruby processor. If it's easy to avoid loading the OpenStudio Model under these situations, I'd be very much in favor of that.

Edit: And indeed we don't call require 'openstudio' in these cases.

kbenne · 2020-07-20T22:10:55Z

" And indeed we don't call require 'openstudio' in these cases." I wouldn't expect that you require openstudio if you aren't using the openstudio api. but what about people who are using the openstudio api but forgot the require? Maybe those people don't exist. or if they do maybe it is ok to break their code

lefticus · 2020-07-21T00:28:31Z

We can use module autoload capability to load Openstudio when it's first used.

There will be a few moving parts.

autoload must be tied to a .rb file, so there will need to be more .rb files embedded
We'll need to expose the code for calling into the executable to register OpenStudio into ruby, back out to ruby (so it can be called by the .rb file mentioned previously)

It should be stable, and doable, but will take some testing to make sure we don't break the various workflows used for openstudio/ruby.

@shorowit I show ~0.2% perf difference between openstudio and openstudio -e "puts 'Hello World'" in my measuring.

kbenne · 2020-07-21T02:37:34Z

go forth @lefticus and make it so if you are able.

lefticus · 2020-07-21T14:45:22Z

@kbenne I'll give it a shot.

* Module.autoload is used to load openstudio_init_extended.rb * Any access to any of the OpenStudio:: sub-namespaces triggers this load On test system "puts 'Hello World'" test decreases from .53s to .33s Addresses #3835

shorowit added the component - CLI label Jan 7, 2020

tijcolem assigned kbenne Jan 10, 2020

joseph-robertson self-assigned this May 8, 2020

kbenne assigned lefticus and unassigned lefticus, kbenne and joseph-robertson Jun 12, 2020

lefticus added a commit that referenced this issue Jul 18, 2020

Avoid copies of embedded_file data

a478258

Addresses #3835

lefticus mentioned this issue Jul 28, 2020

3835 improve cli runtime #4028

Merged

tijcolem closed this as completed in #4028 Aug 7, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve CLI runtime? #3835

Improve CLI runtime? #3835

shorowit commented Jan 7, 2020 •

edited

Loading

tijcolem commented Jan 10, 2020

shorowit commented Mar 9, 2020 •

edited

Loading

joseph-robertson commented Mar 17, 2020

joseph-robertson commented Mar 30, 2020

joseph-robertson commented Mar 30, 2020

joseph-robertson commented Mar 31, 2020 •

edited

Loading

tijcolem commented Jul 10, 2020

lefticus commented Jul 18, 2020 •

edited

Loading

lefticus commented Jul 18, 2020

lefticus commented Jul 18, 2020

lefticus commented Jul 19, 2020

kbenne commented Jul 20, 2020

lefticus commented Jul 20, 2020 •

edited

Loading

shorowit commented Jul 20, 2020 •

edited

Loading

kbenne commented Jul 20, 2020

kbenne commented Jul 20, 2020

shorowit commented Jul 20, 2020 •

edited

Loading

kbenne commented Jul 20, 2020 •

edited

Loading

lefticus commented Jul 21, 2020

kbenne commented Jul 21, 2020

lefticus commented Jul 21, 2020

Improve CLI runtime? #3835

Improve CLI runtime? #3835

Comments

shorowit commented Jan 7, 2020 • edited Loading

tijcolem commented Jan 10, 2020

shorowit commented Mar 9, 2020 • edited Loading

joseph-robertson commented Mar 17, 2020

joseph-robertson commented Mar 30, 2020

joseph-robertson commented Mar 30, 2020

joseph-robertson commented Mar 31, 2020 • edited Loading

tijcolem commented Jul 10, 2020

lefticus commented Jul 18, 2020 • edited Loading

lefticus commented Jul 18, 2020

lefticus commented Jul 18, 2020

lefticus commented Jul 19, 2020

kbenne commented Jul 20, 2020

lefticus commented Jul 20, 2020 • edited Loading

shorowit commented Jul 20, 2020 • edited Loading

kbenne commented Jul 20, 2020

kbenne commented Jul 20, 2020

shorowit commented Jul 20, 2020 • edited Loading

kbenne commented Jul 20, 2020 • edited Loading

lefticus commented Jul 21, 2020

kbenne commented Jul 21, 2020

lefticus commented Jul 21, 2020

shorowit commented Jan 7, 2020 •

edited

Loading

shorowit commented Mar 9, 2020 •

edited

Loading

joseph-robertson commented Mar 31, 2020 •

edited

Loading

lefticus commented Jul 18, 2020 •

edited

Loading

lefticus commented Jul 20, 2020 •

edited

Loading

shorowit commented Jul 20, 2020 •

edited

Loading

shorowit commented Jul 20, 2020 •

edited

Loading

kbenne commented Jul 20, 2020 •

edited

Loading