Why my query not using index to sort?

Is there anyway, I can improve the sorting so that it can use the index ?

Are you telling that why PG is not simply reading the data from the index (which is already in sorted
order)?

Hi Ravi,

Yes you are right. It seems it is doing sorting in memory by name. But I have `name` column in index.

Thanks,

Arup Rakshit
ar@zeit.io

On 9/28/18 6:19 AM, Arup Rakshit wrote:

Hi Ravi,

Yes you are right. It seems it is doing sorting in memory by name. But I
have `name` column in index.

You are looking for the vessels.company_id not vessels.name so not sure
why you expect an index lookup on name?

Thanks,

Arup Rakshit
ar@zeit.io <mailto:ar@zeit.io>

On 28-Sep-2018, at 6:38 PM, Ravi Krishna <srkrishna1@aol.com
<mailto:srkrishna1@aol.com>> wrote:

Is there anyway, I can improve the sorting so that it can use the index ?

Are you telling that why PG is not simply reading the data from the
index (which is already in sorted
order)?

--
Adrian Klaver
adrian.klaver@aklaver.com

Arup Rakshit <ar@zeit.io> writes:

My query is not using name index to sort the result.

Given the rowcounts here, I think the planner is making the right choice.
Sorting 70-some rows with a Sort node is probably cheaper than doing
random disk I/O to get them in sorted order. With more rows involved,
it might make the other choice.

As a testing measure (don't do it in production!), you could set
enable_sort = off, which will force the planner to pick a non-Sort
plan if possible. Then you could see whether that's actually faster
or slower, and by how much.

regards, tom lane

Hello Tom,

Here is the plan with `enable_sort = off`.

# set enable_sort = off; SET
# explain analyze select "vessels" .* from "vessels" where "vessels"."deleted_at" is null and "vessels"."company_id" = '86529964-6e9b-4bfa-ba9e-62bd24eaa954' order by "vessels"."name" ASC;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------
Index Scan using inspector_tool_idx20_1 on vessels (cost=0.27..40.76 rows=76 width=107) (actual time=0.047..0.120 rows=77 loops=1)
Index Cond: (company_id = '86529964-6e9b-4bfa-ba9e-62bd24eaa954'::uuid)
Filter: (deleted_at IS NULL)
Rows Removed by Filter: 4
Planning time: 1.867 ms
Execution time: 0.252 ms
(6 rows)

Why it is showing *6 rows*? Also it seems less than what I had before:

# explain analyze select "vessels" .* from "vessels" where "vessels"."deleted_at" is null and "vessels"."company_id" = '86529964-6e9b-4bfa-ba9e-62bd24eaa954' order by "vessels"."name" ASC;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=17.29..17.48 rows=76 width=107) (actual time=0.789..0.796 rows=77 loops=1)
Sort Key: name
Sort Method: quicksort Memory: 38kB
-> Bitmap Heap Scan on vessels (cost=4.90..14.91 rows=76 width=107) (actual time=0.090..0.122 rows=77 loops=1)
Recheck Cond: (company_id = '86529964-6e9b-4bfa-ba9e-62bd24eaa954'::uuid)
Filter: (deleted_at IS NULL)
Rows Removed by Filter: 4
Heap Blocks: exact=3
-> Bitmap Index Scan on inspector_tool_idx20_1 (cost=0.00..4.88 rows=81 width=0) (actual time=0.059..0.059 rows=81 loops=1)
Index Cond: (company_id = '86529964-6e9b-4bfa-ba9e-62bd24eaa954'::uuid)
Planning time: 1.743 ms
Execution time: 0.954 ms
(12 rows)

Thanks,

Arup Rakshit
ar@zeit.io

Am 28.09.2018 um 16:49 schrieb Arup Rakshit:

�Planning time: 1.867 ms
�Execution time: 0.252 ms
(6 rows)

Why it is showing *6 rows*? Also it seems less than what I had before:

the explain-output are 6 rows ;-)

Regards, Andreas

--
2ndQuadrant - The PostgreSQL Support Company.
www.2ndQuadrant.com

Oh I see. That makes sense, I was reading too much into that line.. :)

Thanks,

Arup Rakshit
ar@zeit.io

Also I meatn the execution time is less than I had before with enable_sort = off. Why 6 rows was a side question. :)

Thanks,

Arup Rakshit
ar@zeit.io

Am 28.09.2018 um 18:03 schrieb Arup Rakshit:

Also I meatn the execution time is less than I had before with
enable_sort = off.

yeah, but not that much. different plan.

Regards, Andreas

--
2ndQuadrant - The PostgreSQL Support Company.
www.2ndQuadrant.com

Yes. But I thought I could improve it, so that it can be finished in 0.xx ms. It takes now between 1.7 to 1.9 ms in production.

Thanks,

Arup Rakshit
ar@zeit.io

On 9/28/18 11:32 AM, Arup Rakshit wrote:

Yes. But I thought I could improve it, so that it can be finished in
0.xx ms. It takes now between 1.7 to 1.9 ms in production.

That is not what you showed in your first post:

Planning time: 0.178 ms
Execution time: 0.527 ms

Thanks,

Arup Rakshit
ar@zeit.io <mailto:ar@zeit.io>

On 28-Sep-2018, at 9:46 PM, Andreas Kretschmer
<andreas@a-kretschmer.de <mailto:andreas@a-kretschmer.de>> wrote:

Am 28.09.2018 um 18:03 schrieb Arup Rakshit:

Also I meatn the execution time is less than I had before with
enable_sort = off.

yeah, but not that much. different plan.

Regards, Andreas

--
2ndQuadrant - The PostgreSQL Support Company.
www.2ndQuadrant.com <http://www.2ndQuadrant.com&gt;

--
Adrian Klaver
adrian.klaver@aklaver.com

Yes, I have shown the explain plan output. But in my application log the sql query prints 1.7 to 1.9 ms.

Thanks,

Arup Rakshit
ar@zeit.io

On 09/28/2018 12:51 PM, Arup Rakshit wrote:

Yes, I have shown the explain plan output. But in my application log
the sql query prints 1.7 to 1.9 ms.

How often does the production app make this call?� Apparently it could
do it 500 times per second.� But at such a rate the network overhead
would be stupendous - you might think about getting more data per call,
few calls.

On 9/28/18 11:51 AM, Arup Rakshit wrote:

Yes, I have shown the explain plan output. But in my application log the
sql query prints 1.7 to 1.9 ms.

So you have added another layer to the process.

The application is?

The log settings are?

What is being printed?

Where is it being printed?

Thanks,

Arup Rakshit
ar@zeit.io <mailto:ar@zeit.io>

--
Adrian Klaver
adrian.klaver@aklaver.com

Hi Adrian,

The application is?

It is Ruby On Rails application

The log settings are?
Where is it being printed?

The default application log, the production.log file.

What is being printed?

Check the gist: https://gist.github.com/aruprakshit/a6bd7ca221c9a13cd583e0827aa24ad6 <https://gist.github.com/aruprakshit/a6bd7ca221c9a13cd583e0827aa24ad6&gt;

Thanks,

Arup Rakshit
ar@zeit.io

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.

Thanks,

Arup Rakshit
ar@zeit.io

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@zeit.io <mailto:ar@zeit.io>

--
Adrian Klaver
adrian.klaver@aklaver.com

Hello Adrian,

I used to consider this time as the sql execution time approximately. I’ll do some research and get back to you. Thanks for mentioning it.

Thanks,

Arup Rakshit
ar@zeit.io

Hello Tom,

I have another query, where I am expecting the sort from index, but it is in memory and takes lot of time.

Query:

explain analyze select
*
from
"standard_workitems"
where
"standard_workitems"."deleted_at" is null
and "standard_workitems"."company_id" = '6fed40b7-fdd7-4efb-a163-c2b42e6486ae'
order by
standard_workitems.item_code asc;

Explain plan:

Sort (cost=3454.03..3458.18 rows=1660 width=810) (actual time=20.302..20.502 rows=2071 loops=1)
Sort Key: item_code
Sort Method: quicksort Memory: 800kB
-> Bitmap Heap Scan on standard_workitems (cost=57.29..3365.25 rows=1660 width=810) (actual time=0.297..0.781 rows=2071 loops=1)
Recheck Cond: ((company_id = '6fed40b7-fdd7-4efb-a163-c2b42e6486ae'::uuid) AND (deleted_at IS NULL))
Heap Blocks: exact=139
-> Bitmap Index Scan on standard_workitems_partial_index_idx_1_1 (cost=0.00..56.87 rows=1660 width=0) (actual time=0.272..0.272 rows=2071 loops=1)
Index Cond: (company_id = '6fed40b7-fdd7-4efb-a163-c2b42e6486ae'::uuid)
Planning time: 0.199 ms
Execution time: 20.688 ms

Indexes I have:

Indexes:
"standard_workitems_pkey" PRIMARY KEY, btree (id)
"index_standard_workitems_on_company_id" btree (company_id)
"index_standard_workitems_on_deleted_at" btree (deleted_at)
"index_standard_workitems_on_item_code" btree (item_code)
"index_standard_workitems_on_workitem_category_id" btree (workitem_category_id)
"standard_workitems_partial_index_idx_1_1" btree (company_id, item_code) WHERE deleted_at IS NULL

Thanks,

Arup Rakshit
ar@zeit.io