ruby-grape
Wrapping simple query in Grape method causing big slowdown (3s+)
Hi, we're struggling to work through an issue where a Rails controller and a Grape API endpoint both run the same underlying ActiveRecord query - literally the same code, and do nothing else, but the controller version runs in average 116ms and the Grape version in average 3.5s.
Here are the two in Skylight, which is great, but doesn't give us the granularity we need to investigate further:
Navbar: https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1561487700/6h/endpoints/Srch::Search%20%5BGET%5D%20srch%2Ftags
Suggested: https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1561487520/6h/endpoints/TagController%23suggested?responseType=json
The code is documented and linked to here: https://github.com/publiclab/plots2/issues/5951
We'd love some advice on how to further investigate, or potentially what else makes these two requests different?
Something is fishy, but it's nice to be looking at an OSS project with all its guts!
Is it the entity rendering that's causing this? The Rails controller version is returning a JSON with @suggestions.collect { |tag| tag.name }.uniq but the Grape API is returning a DocList that is then presented via an Entity. I would start there, how long does DocList.to_json or .serializable_hash take?
You might want to work on better instrumentation. Something like a NewRelic should be able to show you exactly where you are spending time. The graphs provided don't detail any internals.
Hope this helps.
On Tue, Jun 25, 2019 at 9:01 PM Jeffrey Warren [email protected] wrote:
Hi, we're struggling to work through an issue where a Rails controller and a Grape API endpoint both run the same underlying ActiveRecord query - literally the same code, and do nothing else, but the controller version runs in average 116ms and the Grape version in average 3.5s.
Here are the two in Skylight, which is great, but doesn't give us the granularity we need to investigate further:
Navbar: https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1561487700/6h/endpoints/Srch::Search%20%5BGET%5D%20srch%2Ftags
Suggested: https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1561487520/6h/endpoints/TagController%23suggested?responseType=json
The code is documented and linked to here: publiclab/plots2#5951 https://github.com/publiclab/plots2/issues/5951
We'd love some advice on how to further investigate, or potentially what else makes these two requests different?
— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/ruby-grape/grape/issues/1890?email_source=notifications&email_token=AAEEM7YRCQEZSGJBSVDYA7DP4K5XDA5CNFSM4H3NPCM2YY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4G3V4IYQ, or mute the thread https://github.com/notifications/unsubscribe-auth/AAEEM77W3JPQS4DUOMPBBYLP4K5XDANCNFSM4H3NPCMQ .
--
dB. | Moscow - Geneva - Seattle - New York code.dblock.org - t:@dblockdotorg http://twitter.com/#!/dblockdotorg - ig: @artdblockdotorg https://www.instagram.com/artdblockdotorg - github/dblock https://github.com/dblock
Thanks a lot for the quick reply! I tried generating the doclist in the console on the production machine and it was not slow, certainly not seconds long. That's a good suggestion about instrumentation. I think skylight has guidance for something like this too, so I'll look into it.
Yeah, having recently started using skylight it's nice to be able to post it's analysis alongside our code links and the live site API all in the open! I hope it's helpful for you too.
On Tue, Jun 25, 2019, 10:34 PM Daniel Doubrovkine (dB.) @dblockdotorg < [email protected]> wrote:
Something is fishy, but it's nice to be looking at an OSS project with all its guts!
Is it the entity rendering that's causing this? The Rails controller version is returning a JSON with @suggestions.collect { |tag| tag.name }.uniq but the Grape API is returning a DocList that is then presented via an Entity. I would start there, how long does DocList.to_json or .serializable_hash take?
You might want to work on better instrumentation. Something like a NewRelic should be able to show you exactly where you are spending time. The graphs provided don't detail any internals.
Hope this helps.
On Tue, Jun 25, 2019 at 9:01 PM Jeffrey Warren [email protected] wrote:
Hi, we're struggling to work through an issue where a Rails controller and a Grape API endpoint both run the same underlying ActiveRecord query - literally the same code, and do nothing else, but the controller version runs in average 116ms and the Grape version in average 3.5s.
Here are the two in Skylight, which is great, but doesn't give us the granularity we need to investigate further:
Navbar:
https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1561487700/6h/endpoints/Srch::Search%20%5BGET%5D%20srch%2Ftags
Suggested:
https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1561487520/6h/endpoints/TagController%23suggested?responseType=json
The code is documented and linked to here: publiclab/plots2#5951 https://github.com/publiclab/plots2/issues/5951
We'd love some advice on how to further investigate, or potentially what else makes these two requests different?
— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub < https://github.com/ruby-grape/grape/issues/1890?email_source=notifications&email_token=AAEEM7YRCQEZSGJBSVDYA7DP4K5XDA5CNFSM4H3NPCM2YY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4G3V4IYQ , or mute the thread < https://github.com/notifications/unsubscribe-auth/AAEEM77W3JPQS4DUOMPBBYLP4K5XDANCNFSM4H3NPCMQ
.
--
dB. | Moscow - Geneva - Seattle - New York code.dblock.org - t:@dblockdotorg http://twitter.com/#!/dblockdotorg - ig: @artdblockdotorg https://www.instagram.com/artdblockdotorg - github/dblock https://github.com/dblock
— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/ruby-grape/grape/issues/1890?email_source=notifications&email_token=AAAF6JZ53RG7PNSIE5XCKZTP4LIPDA5CNFSM4H3NPCM2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODYSEGWI#issuecomment-505693017, or mute the thread https://github.com/notifications/unsubscribe-auth/AAAF6JZA7WQKLG5ECDWXW2TP4LIPDANCNFSM4H3NPCMQ .
I can see there's only 1 request. Could perhaps a part of that time is spent in pre-loading the app for the first time?
I know in the specs of an app I maintain the first time the get is called it takes circa 3 seconds, but followup get requests take substantially lower time
Thanks, I don't think so, because this is a production app in constant use. And I can select multiple requests and get a similar result:
But I wonder if it could be something like that... some kind of boot time thing for Grape? But I don't imagine Grape itself has a lot of overhead or anything.
OK, trying to add instrumentation at https://github.com/publiclab/plots2/pull/6000