Re: Why my query not using index to sort?

Hello Adrian,

The one I said in gist is different query, and the previous mail I posted another query because I was testing with different types of queries. So 1.5, 1.7 is not for this current one. My main point now I am trying to understand why it is not matching at all. The current query timing in psql and production log is very close, but not the explain output.

Regarding the file written time, I think it is not the time to write into the file. Because If I don’t write this to the file still it shows 14ms + always. I used the file not the sql output so that I can paste here clean stuffs I want to show. If you want, I can show the output without writing it to the external file, and you will see the same time.

docking_dev=# \timing on Timing is on.
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');
code | name | technical_details | created_at | updated_at | deleted_at | id | company_id | vessel_category_id
------------+-------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+----------------------------+------------+--------------------------------------+--------------------------------------+--------------------------------------
HHS | Hamburg Star | {"class_number":"9298325","owner_salutation":"Dear Mr.","charterer":"Scorpio","overview_docking_dates":"2015-07-18T22:00:00.000+00:00","cr_last_date":"2010-12-22","cr_due_date":"2010-12-21","edd_vessel":"No","imo_number":"9298325","classification_society":"Lloyds Register","flag_state":"Liberia","port_of_registry":"Monrovia","scantling_deadweight":"73748,55","gross_tonnage":"41968","net_tonnage":"22047","breadth":"32,26","length_pp":"218,0","length_overall":"228,6","docking_draft":"5,5","scantling_draft":"14,45","lightship_weight":"15000,07","type_of_vessel":"Oil/Product Carrier","main_engine_fuel_type":"IFO 380","auxiliary_engines_maker":"Yanmar","auxiliary_engines_types":"8 21L-EV","auxiliary_engines_output":"900 kW","owner_name":"MT Hamburg Star Schiffahrtsgesellschaft mbh \u0026 Co. KG","official_number":"91186","commissioned":"2005-12-22","liquid_cargo_intake":"83611,31","depth_to_main_deck":"20,8","class_assignment":"Oil / Product, 100 A1 Oil tanker, ESP, *IWS, LI, LMC, UMS, IGS","main_engine_type_and_make":"B \u0026 W 5S60 MC-C, 11.300 kW, 105 rpm"} | 2015-06-29 13:19:44.449149 | 2015-07-09 07:21:43.842282 | | 113e113d-9fbe-4429-99a6-c8ed306f9e29 | e8cd498d-9da5-4d54-ac07-e4fc48c84a67 | 18497ecf-5435-4e76-bc13-cda11f106457
4020 | Hansa Fyn | {"vessels_registered_name":"Hansa Fyn","type_of_vessel":"Container Geared","imo_number":"9256418","official_number":"20276","class_number":"110280","builder_hull_number":"GWS 299","classification_society":"DNV GL","class_assignment":"GL 100 A5 E CONTAINER SHIP, SOLAS II-2 Reg., 54 IW","flag_state":"Grand Duchy of Luxembourg","port_of_registry":”Lux
Time: 14.173 ms
docking_dev=#
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.201..2.927 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: 0.528 ms
Execution time: 3.076 ms
(5 rows)

Thanks,

Arup Rakshit
ar(at)zeit(dot)io

> On 01-Oct-2018, at 3:15 AM, Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com> wrote:
>
> 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 <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 <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> <mailto: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> <mailto: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 <mailto:adrian(dot)klaver(at)aklaver(dot)com>