Re: Why my query not using index to sort?

On 9/30/18 1:21 PM, Arup Rakshit wrote:
> Hi Adrian,
>
> I am on psql (10.5, server 9.5.14).
>
> I am still investigating the Rails side. I found a blog
> (https://schneems.com/2015/10/27/sql-in-rails-logs.html) , where a Rails
> core team member said that Load time is basically SQL execution time.

From what I read he said it is the SQL call, with no indication of
whether that includes the the ORM/framwork overhead to make the call or not.

>
> I also had done a little test on psql. Here I also see the explain
> output and actual execution time far apart and it matches what I see in
> the Rails log.

No it does not. In a previous post you said:

"It takes now between 1.7 to 1.9 ms in production."

Which was confirmed by the information here:

https://gist.github.com/aruprakshit/a6bd7ca221c9a13cd583e0827aa24ad6

Below you show 5.046 ms and then 14.377 ms. The second number is not
really relevant as it includes the time to write out to a file, so is
different operation all together.

>
> docking_dev=# explain analyze select
>
>                                                             "vessels"
> .*
>
>                                                   from
>
>
>                                       "vessels"
>
>
>                           where
>
>
>               "vessels"."deleted_at" is null
>
>
>   and "vessels"."company_id" in
> ('6f56abfe-a355-44b9-b728-a642f661a8e7',
>
>                               'c82d08d7-bec1-4413-b627-63e1898c568c',
>
>
>                   '5404cd95-29d9-44c3-8ca3-261be373bf31',
>
>
>       '19d5224a-ff2b-43c4-b756-4e82c29a4712',
>
>
> '6fed40b7-fdd7-4efb-a163-c2b42e6486ae',
>
>
> 'a0793a69-330c-4a6b-8a55-ee6daf574371',
>
>
> '3e936613-04e6-4db0-8595-5b8ae9cc2a40',
>
>
> '059275e2-933d-4543-8eef-91a5af87849b',
>
>
> 'c64a658a-6ff1-4e76-8551-dfa62383bac3',
>
>
> 'ce634593-555a-4f3c-af79-d7a7cf3796fb',
>
>
> 'e18c4dab-f536-46f8-9f85-8bf51dbe989e',
>
>
> 'cfe6a534-b33b-4493-862e-6aa4f0b4a790',
>
>
> '58d628c1-af0d-4e64-b672-87c77b677c7b',
>
>
> '36cb8ab0-5e8a-40db-a296-5e4b5dc666f3',
>
>
> '0d15288d-c042-461e-b4cb-0b2ad47ead29',
>
>
> 'e8cd498d-9da5-4d54-ac07-e4fc48c84a67',
>
>
> 'c192c117-0ec7-4c1d-94a6-0a773e70e58b',
>
>
> '97dd15db-5862-4d49-9047-e3e0307e5c95',
>
>
> '03766e4f-4f64-4927-be6d-a126958ac1a8',
>
>
> '26987b95-8652-491c-b950-4fb3128f4714',
>
>
> 'c4f55044-3f4e-439e-a586-8b6978c7b406',
>
>
> '36825da8-2f58-4a62-bdb4-2b91cbe18299',
>
>
> 'cca256cf-b415-472c-8b9f-a8432d02c580');
>
>
>
>
>
>
>                         QUERY PLAN
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>  Seq Scan on vessels  (cost=0.00..630.62 rows=923 width=1439) (actual
> time=0.279..4.921 rows=753 loops=1)
>    Filter: ((deleted_at IS NULL) AND (company_id = ANY
> ('{6f56abfe-a355-44b9-b728-a642f661a8e7,c82d08d7-bec1-4413-b627-63e1898c568c,5404cd95-29d9-44c3-8ca3-261be373bf31,19d5224a-ff2b-43c4-b756-4e82c29a4712,6fed40b7-fdd7-4efb-a163-c2b42e6486ae,a0793a69-330c-4a6b-8a55-ee6daf574371,3e936613-04e6-4db0-8595-5b8ae9cc2a40,059275e2-933d-4543-8eef-91a5af87849b,c64a658a-6ff1-4e76-8551-dfa62383bac3,ce634593-555a-4f3c-af79-d7a7cf3796fb,e18c4dab-f536-46f8-9f85-8bf51dbe989e,cfe6a534-b33b-4493-862e-6aa4f0b4a790,58d628c1-af0d-4e64-b672-87c77b677c7b,36cb8ab0-5e8a-40db-a296-5e4b5dc666f3,0d15288d-c042-461e-b4cb-0b2ad47ead29,e8cd498d-9da5-4d54-ac07-e4fc48c84a67,c192c117-0ec7-4c1d-94a6-0a773e70e58b,97dd15db-5862-4d49-9047-e3e0307e5c95,03766e4f-4f64-4927-be6d-a126958ac1a8,26987b95-8652-491c-b950-4fb3128f4714,c4f55044-3f4e-439e-a586-8b6978c7b406,36825da8-2f58-4a62-bdb4-2b91cbe18299,cca256cf-b415-472c-8b9f-a8432d02c580}'::uuid[])))
>    Rows Removed by Filter: 1947
>  Planning time: 2.249 ms
>  Execution time: 5.046 ms
> (5 rows)
>
> docking_dev=# \timing on
> Timing is on.
> docking_dev=# \o ~/Downloads/a.txt
>
>
> docking_dev=# select
>
>                                                             "vessels"
> .*
>
>                                                   from
>
>
>                                       "vessels"
>
>
>                           where
>
>
>               "vessels"."deleted_at" is null
>
>
>   and "vessels"."company_id" in
> ('6f56abfe-a355-44b9-b728-a642f661a8e7',
>
>                               'c82d08d7-bec1-4413-b627-63e1898c568c',
>
>
>                   '5404cd95-29d9-44c3-8ca3-261be373bf31',
>
>
>       '19d5224a-ff2b-43c4-b756-4e82c29a4712',
>
>
> '6fed40b7-fdd7-4efb-a163-c2b42e6486ae',
>
>
> 'a0793a69-330c-4a6b-8a55-ee6daf574371',
>
>
> '3e936613-04e6-4db0-8595-5b8ae9cc2a40',
>
>
> '059275e2-933d-4543-8eef-91a5af87849b',
>
>
> 'c64a658a-6ff1-4e76-8551-dfa62383bac3',
>
>
> 'ce634593-555a-4f3c-af79-d7a7cf3796fb',
>
>
> 'e18c4dab-f536-46f8-9f85-8bf51dbe989e',
>
>
> 'cfe6a534-b33b-4493-862e-6aa4f0b4a790',
>
>
> '58d628c1-af0d-4e64-b672-87c77b677c7b',
>
>
> '36cb8ab0-5e8a-40db-a296-5e4b5dc666f3',
>
>
> '0d15288d-c042-461e-b4cb-0b2ad47ead29',
>
>
> 'e8cd498d-9da5-4d54-ac07-e4fc48c84a67',
>
>
> 'c192c117-0ec7-4c1d-94a6-0a773e70e58b',
>
>
> '97dd15db-5862-4d49-9047-e3e0307e5c95',
>
>
> '03766e4f-4f64-4927-be6d-a126958ac1a8',
>
>
> '26987b95-8652-491c-b950-4fb3128f4714',
>
>
> 'c4f55044-3f4e-439e-a586-8b6978c7b406',
>
>
> '36825da8-2f58-4a62-bdb4-2b91cbe18299',
>
>
> 'cca256cf-b415-472c-8b9f-a8432d02c580');
> Time: 14.377 ms
> docking_dev=#
>
>
> Thanks,
>
> Arup Rakshit
> ar(at)zeit(dot)io <mailto:ar(at)zeit(dot)io>
>
>
>
>> On 29-Sep-2018, at 2:50 AM, Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com
>> <mailto:adrian(dot)klaver(at)aklaver(dot)com>> wrote:
>>
>> On 9/28/18 12:14 PM, Arup Rakshit wrote:
>>> Forgot to mention in my previous email, it was a quick send click.
>>> Sorry for that.
>>> In the gist you need to see all the line with Vessel Load(.. . I load
>>> the page multiple times to catch the different times, so you will the
>>> line multiple times there in the log file.
>>
>> Do you know what Vessel Load () is actually measuring?
>>
>> To me it looks like it is covering both the query(including ROR
>> overhead) and the HTTP request/response cycle.
>>
>> Also have you looked at:
>>
>> https://guides.rubyonrails.org/debugging_rails_applications.html#impact-of-logs-on-performance
>>
>>> Thanks,
>>> Arup Rakshit
>>> ar(at)zeit(dot)io <mailto:ar(at)zeit(dot)io>
>>
>>
>> --
>> Adrian Klaver
>> adrian(dot)klaver(at)aklaver(dot)com
>

--
Adrian Klaver
adrian(dot)klaver(at)aklaver(dot)com