Performance: Ruby interpreter init can cause 5 sec latency in requests
Closed this issue · 16 comments
I'd upgraded my Packal packages a couple months ago and gotten a newer version of this workflow. Performance was not great -- 3-4 seconds to show the auto-complete list, where I was used to << 1 second, before.
I updated again a week ago, and performance is much better. It's back to the <<1 second latency I was used to. I use this at least 5 times every day. Thanks for writing a solid tool!
No issue, just a 'thanks'.
Closing.
Actually, I realized what happened. My Packal updater had switched this back to 1.3. That made performance more like I expect. I'll hold off on 2.x until the 3-4 second latency is improved.
I would need more detail to understand what the issue is.
When is the latency? Every single time you open Alfred? How many files do you have on your Google Drive?
Providing the log would be a good start, as it shows number of items, times it took to get results from Google Drive, etc.
Thanks for the help.
I counted files using this method: https://www.lifehacker.com.au/2013/08/how-to-count-files-in-a-google-drive-folder/
I see "Zipping 164 files". From the debug logs, it looks like I have access to ~500 files. I'm not sure what the method above is counting. I guess the balance is the count of files shared with me.
There is lots of detail in the debug logs. I'm going to mask the most obvious things and then share securely with you, @sorbits.
Shared in a private repo.
Logs show ~0.132 seconds to retrieve results in the 1.3.0 version. The same search "one thing", which I expect will retrieve a single file out of ~500, appear to take 6.71 seconds in the 2.1.0 version. I ran the search on the new version several times, to make sure there weren't caching differences. The response times were in the ~5-6 second range each time. The tool is still quite useful, but it is hard to get used to. It's a 50x longer response time than the previous version, if I'm understanding the debug output correctly.
I see 516-521 files being returned in each version. The 1.3.0 version seems to print ~600 files in debug mode before the query is run, which I expect is the contents of the local file cache.
You can access the workflow’s log directly instead of going via Alfred (which has a lot of extra noise), see troubleshooting in the README.
However, from your log, I see two executions, the first with an empty cache that take ~6 seconds to get all the data from Google Drive, but then a second run which is this:
[2017-10-16 15:25:23.842] [22148] [DEBUG] ./google-drive.rb ["--filter", "one thing"]
[2017-10-16 15:25:23.858] [22148] [DEBUG] Loaded 766 items from cache (created 13 seconds ago)
[2017-10-16 15:25:23.863] [22148] [DEBUG] Execution took 0.021 seconds
So things seems to work as they should with sub-second loading of items from cache.
Ah. I'd totally missed the README section. Apologies.
Cached behavior is only occurring in 1.3.0, though. How long do I wait for (or trigger) the cache to fill in 2.1.0?
Response in the UI is still in the ~5-6 sec range for those same queries. I disregarded those times in my analysis, for that reason.
I don't see how more query volume would affect cache efficacy, based on how it appears to work, but I can try that. I'll let this version run for the day and see if I start to see faster responses in the UI.
OK, I figured this out.
If I explicitly set the ruby interpreter to my default Homebrew-installed one, performance is sub-second as I expect:
/usr/local/bin/ruby ./google-drive.rb --filter "$1"
The latency was in the startup of the Mac-default ruby interpreter, for reasons I don't completely understand. There is a 5+ second delay between the last Alfred "Argument queued" message and the first debug message in google-drive.rb.
5 sec delay, with detailed environment logging added:
[2017-10-17 15:17:20][input.scriptfilter] Queuing argument 'one thing'
[2017-10-17 15:17:31][input.scriptfilter] Script with argument 'one thing' finished
[2017-10-17 15:17:31][STDERR: input.scriptfilter] [2017-10-17 15:17:30.883] [11176] [DEBUG] Ruby version: 2.3.3p222
[2017-10-17 15:17:30.883] [11176] [DEBUG] Ruby path: /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby
[2017-10-17 15:17:30.883] [11176] [DEBUG] Starting logger at ./google-drive.rb with args ["--filter", "one thing"]
[2017-10-17 15:17:30.883] [11176] [DEBUG] Starting main at ./google-drive.rb with args ["--filter", "one thing"]
[2017-10-17 15:17:30.885] [11176] [DEBUG] Loaded 13 releases from cache (created a day ago)
[2017-10-17 15:17:30.885] [11176] [DEBUG] Latest online version is v2.1, we are running 2.1
[2017-10-17 15:17:30.942] [11176] [DEBUG] Loaded 766 items from cache (created 6 minutes ago)
[2017-10-17 15:17:30.947] [11176] [DEBUG] Execution took 0.064 seconds
[2017-10-17 15:17:30.947] [11176] [DEBUG] No cache update needed.
There's an 11 second interval between my last input and the script end, only 0.064 sec of which is explained by google-drive.rb's internal work.
When I explicitly set the ruby interpreter to the one 'rvm system' uses, provided by Homebrew on my system, the 5 sec interpreter startup delay goes away:
[2017-10-17 15:26:41][input.scriptfilter] Queuing argument 'one thing'
[2017-10-17 15:26:42][input.scriptfilter] Script with argument 'one thing' finished
[2017-10-17 15:26:42][STDERR: input.scriptfilter] [2017-10-17 15:26:42.127] [13121] [DEBUG] Ruby version: 2.4.0p0
[2017-10-17 15:26:42.127] [13121] [DEBUG] Ruby path: /usr/local/Cellar/ruby/2.4.0/bin/ruby
[2017-10-17 15:26:42.127] [13121] [DEBUG] Starting logger at ./google-drive.rb with args ["--filter", "one thing"]
[2017-10-17 15:26:42.127] [13121] [DEBUG] Starting main at ./google-drive.rb with args ["--filter", "one thing"]
[2017-10-17 15:26:42.128] [13121] [DEBUG] Loaded 13 releases from cache (created a day ago)
[2017-10-17 15:26:42.128] [13121] [DEBUG] Latest online version is v2.1, we are running 2.1
[2017-10-17 15:26:42.136] [13121] [DEBUG] Loaded 766 items from cache (created a minute ago)
[2017-10-17 15:26:42.141] [13121] [DEBUG] Execution took 0.014 seconds
[2017-10-17 15:26:42.141] [13121] [DEBUG] No cache update needed.
Note that my MacOS framework and Hombrew-provided ruby environments are pretty clean. I use rvm as needed. I really can't explain why they behave so differently.
$ /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/irb
irb(main):001:0> $:
=> ["/Library/Ruby/Gems/2.3.0/gems/did_you_mean-1.0.0/lib", "/Library/Ruby/Site/2.3.0", "/Library/Ruby/Site/2.3.0/x86_64-darwin17", "/Library/Ruby/Site/2.3.0/universal-darwin17", "/Library/Ruby/Site", "/System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/lib/ruby/vendor_ruby/2.3.0", "/System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/lib/ruby/vendor_ruby/2.3.0/x86_64-darwin17", "/System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/lib/ruby/vendor_ruby/2.3.0/universal-darwin17", "/System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/lib/ruby/vendor_ruby", "/System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/lib/ruby/2.3.0", "/System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/lib/ruby/2.3.0/x86_64-darwin17", "/System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/lib/ruby/2.3.0/universal-darwin17"]
irb(main):002:0> quit
$ which ruby
/usr/local/bin/ruby
$ /usr/local/bin/irb
irb(main):001:0> $:
=> ["/usr/local/lib/ruby/gems/2.4.0/gems/did_you_mean-1.1.0/lib", "/usr/local/lib/ruby/site_ruby/2.4.0", "/usr/local/lib/ruby/site_ruby/2.4.0/x86_64-darwin16", "/usr/local/lib/ruby/site_ruby", "/usr/local/lib/ruby/vendor_ruby/2.4.0", "/usr/local/lib/ruby/vendor_ruby/2.4.0/x86_64-darwin16", "/usr/local/lib/ruby/vendor_ruby", "/usr/local/Cellar/ruby/2.4.0/lib/ruby/2.4.0", "/usr/local/Cellar/ruby/2.4.0/lib/ruby/2.4.0/x86_64-darwin16"]
irb(main):002:0>
I'm fine setting the path explicitly, for now, but I expect this could cause problems for others. Is there a more robust way to select an interpreter?
Is there a more robust way to select an interpreter?
Best would definitely be to find out why your default ruby interpreter has an issue. Try run this in a terminal:
time ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'webrick' -r'shellwords' -r'fileutils' -r'logger' -r'tempfile' -r'open-uri'
If this shows a slow run time, please remove the -r arguments to see if any of them is the culprit (ideally pinpoint the one that is causing the slow load).
Thanks! Webrick is the issue when using MacOS system Ruby. It causes ~5 sec longer ruby interpreter load times when it's required. Webrick require happens quickly in my Homebrew-provided interpreter.
To my knowledge, I haven't done anything at all to my MacOS framework version of my Ruby $LOAD_PATH. It should be whatever's provided with High Sierra, by default.
Detailed checks:
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'webrick' -r'shellwords' -r'fileutils' -r'logger' -r'tempfile'
test
real 0m5.250s
user 0m0.169s
sys 0m0.054s
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'webrick' -r'shellwords' -r'fileutils'
test
real 0m5.237s
user 0m0.166s
sys 0m0.052s
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'webrick'
test
real 0m5.218s
user 0m0.151s
sys 0m0.047s
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri'
test
real 0m0.156s
user 0m0.109s
sys 0m0.035s
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json'
test
real 0m0.175s
user 0m0.118s
sys 0m0.039s
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'webrick'
test
real 0m5.246s
user 0m0.171s
sys 0m0.058s
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'shellwords' -r'fileutils' -r'logger' -r'tempfile'
test
real 0m0.213s
user 0m0.146s
sys 0m0.048s
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'webrick'
test
real 0m5.208s
user 0m0.128s
sys 0m0.053s
bash-4.4$ time /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'shellwords' -r'fileutils' -r'logger' -r'tempfile'
test
real 0m0.174s
user 0m0.119s
sys 0m0.040s
bash-4.4$ time ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'webrick' -r'shellwords' -r'fileutils' -r'logger' -r'tempfile'
test
real 0m0.378s
user 0m0.184s
sys 0m0.078s
bash-4.4$ time /usr/local/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'webrick' -r'shellwords' -r'fileutils' -r'logger' -r'tempfile'
test
real 0m0.286s
user 0m0.201s
sys 0m0.052s
bash-4.4$ time /usr/local/bin/ruby -e 'puts :test' -r'socket' -r'net/http' -r'net/https' -r'uri' -r'json' -r'webrick' -r'shellwords' -r'fileutils' -r'logger' -r'tempfile'
test
real 0m0.233s
user 0m0.160s
sys 0m0.043s
I'm not a Ruby dev, but it looks straightforward. The crudest way would be to move that require to the Auth class.
Another would be to split out a second script and refactor the Auth logic into it. I'll just move that require, since it appears you're trying to stay to one rb file, here. Sound good?