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@xxxxxxx <mailto:ar@xxxxxxx>
On 29-Sep-2018, at 2:50 AM, Adrian Klaver <adrian.klaver@xxxxxxxxxxx
<mailto:adrian.klaver@xxxxxxxxxxx>> 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@xxxxxxx <mailto:ar@xxxxxxx>
--
Adrian Klaver
adrian.klaver@xxxxxxxxxxx
--
Adrian Klaver
adrian.klaver@xxxxxxxxxxx
