Different query plan when trying to analyze performance

[Joerg_Brandeis]

I am currently trying to analyze why one particular query performs worse than expected. While doing that i noticed that the query plan shown when executing the query manually does not match up with the query plan used when the query is dispatched by our server. This makes it very hard to analyze the performance issue, since i then only have the cached plan available and the manually executed query performs far better.

This is the query being executed (simplified):

SELECT h.* FROM horse h
INNER JOIN horse_number hn ON hn.horse_id = h.id
INNER JOIN number n ON n.id = hn.number_id
WHERE lower(n.number) LIKE '%de 224%' escape '!' LIMIT 30;

And some table metrics:

• hn.horse_id is indexed
• h.id is a primary key
• n.id is a primary key
• hn.number_id is a unique key
• n.number is indexed (not full text)

Sizes (Rows):

• Horse: 2.8M
• Horse Number: 2.8M
• Number: 4.87M

Here are the two plans (zoomed out):

1. Cached Plan (executed by our server):

2. Plan for manual execution of the same query:

And here are some performance metrics to highlight the difference in execution time

1. Executed by our server

and a trace log where the execution can also be observed:

# begin setAutoCommit (thread 130313, con-id 344489) at 2022-04-12 13:16:51.247386
# con info [con-id 344489, tx-id 26, cl-pid 24592, cl-ip 10.78.26.254, user: xxx, schema: xxx]
con_c44489.setautocommit(False)
# begin prepareStatement (thread 51835, con-id 344489) at 2022-04-12 13:16:51.247774
# con info [con-id 344489, tx-id 26, cl-pid 24592, cl-ip 10.78.26.254, user: xxx, schema: xxx]
cursor_140289778665472_c44489 = con_c44489.cursor()
# end prepareStatement (thread 51835, con-id 344489) at 2022-04-12 13:16:51.248029
# begin PreparedStatement_execute (thread 130313, con-id 344489) at 2022-04-12 13:16:51.249261
# con info [con-id 344489, tx-id 26, cl-pid 24592, cl-ip 10.78.26.254, user: xxx, schema: xxx]
cursor_140289778665472_c44489.execute(''' select horse0_.id as id1_135_, horse0_.created_by_account_id as created_by_account_id26_135_, horse0_.created_by_organization_id as created_by_organization_id27_135_, horse0_.creation_time as creation_time2_135_, horse0_.last_modified as last_modified3_135_, horse0_.modified_by_account_id as modified_by_account_id28_135_, horse0_.breed as breed4_135_, horse0_.breeding_name as breeding_name5_135_, horse0_.color as color6_135_, horse0_.dam_id as dam_id29_135_, horse0_.dam_name as dam_name7_135_, horse0_.dam_of_dam as dam_of_dam8_135_, horse0_.dam_of_sire as dam_of_sire9_135_, horse0_.date_of_birth as date_of_birth10_135_, horse0_.fei_id as fei_id11_135_, horse0_.first_breeding_activity_year as first_breeding_activity_year12_135_, horse0_.gender as gender13_135_, horse0_.height as height14_135_, horse0_.image_url as image_url15_135_, horse0_.is_pony as is_pony16_135_, horse0_.last_coggins_date as last_coggins_date17_135_, horse0_.last_vaccination_date as last_vaccination_date18_135_, horse0_.micro_chip_number as micro_chip_number19_135_, horse0_.name as name20_135_, horse0_.permanent_bridle_number as permanent_bridle_number21_135_, horse0_.sire_id as sire_id30_135_, horse0_.sire_name as sire_name22_135_, horse0_.sire_of_dam_id as sire_of_dam_id31_135_, horse0_.sire_of_dam_name as sire_of_dam_name23_135_, horse0_.sire_of_sire as sire_of_sire24_135_, horse0_.studbook_id as studbook_id32_135_, horse0_.ueln as ueln25_135_ from horse horse0_ inner join horse_national_registration nationalre1_ on horse0_.id=nationalre1_.horse_id inner join national_registration nationalre2_ on nationalre1_.national_registration_id=nationalre2_.id where lower(nationalre2_.number) like ? escape '!' limit ? ''', ('''%de 441410768301%''', 30))
# end PreparedStatement_execute (thread 130313, con-id 344489) at 2022-04-12 13:16:51.737367
# begin commit (thread 130312, con-id 344489) at 2022-04-12 13:16:54.044500
# con info [con-id 344489, tx-id 26, cl-pid 24592, cl-ip 10.78.26.254, user: xxx, schema: xxx]
con_c44489.commit()
# end commit (thread 130312, con-id 344489) at 2022-04-12 13:16:54.044659

2. Executed manually:

As you can see the manual execution is a lot faster and judging by the complexity of the query the execution time when executed by our server seems far too high. What are the next steps i should be talking to analyze this further?

EDIT: Zooned in query plans:

1. Server

2. Manual:

Thanks!

[Joerg_Brandeis]

Hi Tobias,

i can see 3 tables in your query, 3 table accesses in the plan of your manual execution, but 2 table accesses in the cached plan. So this looks like a plan for a different query, right?

Regards,
Jörg

[puelo]

jbrandeis Thanks for the answer. It seems that both use all 3 tables tho (the query is 100% identical)

Cached (executed by Server):

for query:

select horse0_.* from horse horse0_ 
inner join horse_national_registration nationalre1_ on horse0_.id=nationalre1_.horse_id 
inner join national_registration nationalre2_ on nationalre1_.national_registration_id=nationalre2_.id 
where lower(nationalre2_.number) like ? escape '!' limit ?

and executed manually:

for query:

select horse0_.*  from horse horse0_ 
inner join horse_national_registration nationalre1_ on horse0_.id=nationalre1_.horse_id 
inner join national_registration nationalre2_ on nationalre1_.national_registration_id=nationalre2_.id 
where lower(nationalre2_.number) like '%de 441410768301%' escape '!' limit 30 
WITH HINT(IGNORE_PLAN_CACHE)

[puelo]

jbrandeis

I also added the zoomed in version of the two query plans.

[Cocquerel]

For my knowledge, how do you get this graphical visualisation of the server "cached plan" ? I only know the method via "execute PlanViz" menu when executing manually.

[puelo]

mickael.cocquerel

I use the HANA Tools in Eclipse. In the administration tools under performance you can view the SQL Plan Cache, right-clicking on one row gives you the option to Visualize the plan:

[Joerg_Brandeis]

Hello Tobias,

I can't tell you why different plans are executed.

But the reason for the different performance is clearly visible. In the manual case, filtering is done directly at the table. In the server-side execution, the JOIN takes place first with the full set of data and filtering is done later.

Maybe the push-down of the WHERE condition works better if you already store the data in lowercase and don't need a LOWER function anymore.

Many greetings,

Jörg

[puelo]

jbrandeis

Thanks! We eliminated the need to check with wildcards (so no LIKE '%%'). That, unsurprisingly, sped up the query significantly. It would still be interesting to find out why the other queries were executed differently. Do you think it might be worth a try to execute manually with different hints?

[lbreddemann]

Generally speaking, query optimisers are deterministic, i.e. given the same input they return the same output.

That means, the input (query text, context, data structure information, do parameters) must have been different, when the “bad” plan had been computed.

Maybe the data volume did change considerably since the “bad” plan had been created, but not enough to re-optimise the query.

One thing that struck me was the description of the indexing scheme.

Writing “column x is a primary key”, “column x is a unique key”, and “column x is indexed” is pretty much the same thing for column tables. Putting on a single column index on “number” does not seem helpful at this point - it doesn’t help with the LIKE condition and effectively doubles the storage size of the column. The table only has a few million entries anyhow - raw scanning should do quick business with that.

So, I’d probably go and try to reproduce the bad plan, by first removing the old plan from the query cache. If the plans still differ, the next step would be to activate and read the optimiser traces.

[puelo]

lars.breddemann

The index on the number column was only added after we noticed the bad performance of the query in an, futile, attempt to remedy this.

The volume indeed has changed (~1M new entries in a somewhat short span of time) so this might be one route to investigate. I might have not read carefully enough, but do you know how long a query plan is cached for?

We will remove the index again and i'll try to clear the plan cache and try again.

[lbreddemann]

Plan cache entries don’t have an “expiration date”; they may be invalidated or pushed out of the cache if not used anymore & more entries should be added to the already full cache

[puelo]

lars.breddemann

I think i found why the generated plans were different: I didn't take into account that the statement comes as a prepared statement from our server which obviously leads to a different query plan compared to a query with "fixed" parameters.

Another question (somewhat related): We found that our query runs considerably slower when we use the LOWER function to compare case insensitive. What could be the reason for this? Is there anything we can analyze to see why it differs that much? The query plans are hugely different there as well.

[lbreddemann]

Ok, the difference between prepared and direct statements for optimisation can be significant. It's possible to also use prepared statements in HANA Studio (including for PlanViz), so the difference should be reproducible.

As for the impact of the LOWER function: this adds a lot of extra computation to the filtering.
With a direct equality filter, the filtering can be performed based on the column value dictionary, i.e. the valueID is retrieved from the columns' dictionary and then the colunm is scanned against this valueID via very efficient SIMD code.

As soon as the filter condition cannot be directly checked against the stored values, all possible values from the dictionary need to be materialised, computed based on the filter condition (in this case, all values need to be passed through the LOWER function). This requires additional memory and CPU time and instead of a simple equality test against the column valueIDs, the column needs to be checked against a whole array of matching value IDs. This is because different values, say "Test", "teST", and "TeSt" would all end up matching the condition lower(<column>) = "test". HANA now needs to check the column for entries with valueIDs that point to all three values ("Test", "teST", and "TeSt").

It should be easy to see, how this also impacts cardinality estimates considerably. which easly can change execution plans.

If reasonably possible, I'd try and avoid "dynamic case-insensitive" search. If this has to be enabled, I would look into pre-computing the result of the lower() function in a generated column and use this to filter against. This additional will require less or equal space than the original column and allow for efficient filtering. This approach is the functional equivalent of a function based index, say, in Oracle.

[puelo]

lars.breddemann

Thanks for the detailed answer. Yes, i was able to reproduce the bad performance in Eclipse with HANA Tools and a prepared statement. As you already said the step to "Materialize Results" takes the most time. We went with the solution where we add another column which will hold a completely case insensitive value so that we can search there instead. I will add a conclusion as an answer here.

[puelo · Accepted solution]

After the help of the comment section and more analyzing, the difference in query plans was caused by not using a prepared statement when executing the query manually, which obviously will have another query plan. After using the same prepared statement i was able to reproduce the bad performance and ultimately came to the conclusion that it was caused by a dynamic case insensitive search using the LOWER function.