search

azai91 / alfred-drive-workflow

Alfred workflow to search google drive
MIT License
224 stars 23 forks source link

Performance: Ruby interpreter init can cause 5 sec latency in requests #41

Closed markschwarz closed 6 years ago

markschwarz commented 7 years ago

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'.

markschwarz commented 7 years ago

Closing.

markschwarz commented 7 years ago

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.

sorbits commented 7 years ago

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?

sorbits commented 7 years ago

Providing the log would be a good start, as it shows number of items, times it took to get results from Google Drive, etc.

markschwarz commented 7 years ago

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.

markschwarz commented 7 years ago

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.

sorbits commented 7 years ago

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.

markschwarz commented 7 years ago

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?

sorbits commented 7 years ago

Based on what I pasted from your log, caching is working fine.

The first time you run the workflow, it will create the cache.

Then it will use the cache.

If the cache is more than 10 minutes old, it will refresh the cache in the background (so still instant returns).

I suggest you run multiple queries to build up a longer log and verify that indeed it returns results from the cache, and execution (when loading from cache) is < 1 second.

On 17 Oct 2017, at 17:18, Mark Schwarz wrote:

Ah. I'd totally missed the README section. Apologies. The log file name is slightly different in the new version: ~/Library/Caches/com.runningwithcrayons.Alfred-3/Workflow
Data/com.drive.azai91/com.drive.azai91.log"

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?

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/azai91/alfred-drive-workflow/issues/41#issuecomment-337263370

markschwarz commented 7 years ago

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.

markschwarz commented 7 years ago

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?

sorbits commented 7 years ago

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).

markschwarz commented 7 years ago

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
sorbits commented 7 years ago

Since Webrick is only required to receive the initial OAuth2 token we can delay the require of Webrick to the “starting HTTP server” code path.

Would of course be good to know why Webrick is slow to load on your system, but skipping it when we do not need it (which would be all but first run) is an OK workaround with me.

Are you able to create a PR for the above?

On 18 Oct 2017, at 18:32, Mark Schwarz wrote:

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

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/azai91/alfred-drive-workflow/issues/41#issuecomment-337650027

markschwarz commented 7 years ago

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?

sorbits commented 7 years ago

Yes, just moving the require would be the best solution, but please test after the change.

There should be a sign out action you can select from Alfred to remove tokens, to ensure it is able to obtain new OAuth token after the change.

On 20 Oct 2017, at 22:54, Mark Schwarz wrote:

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?

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/azai91/alfred-drive-workflow/issues/41#issuecomment-338247087