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. 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. 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 a...@zeit.io > On 29-Sep-2018, at 2:50 AM, Adrian Klaver <adrian.kla...@aklaver.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 >> a...@zeit.io <mailto:a...@zeit.io> > > > -- > Adrian Klaver > adrian.kla...@aklaver.com
