oracle-enhanced: Schema loading performance regression after update from rails 5.1 to rails 5.2

Steps to reproduce

Background is that we’re experiencing massive performance issues since updating to rails 5.2. Looking at the logs, it seems that structural database statements make the difference. To isolate this, we performed db:cache:dump multiple times, both with rails 5.1 and rails 5.2.

The difference is startling (see next 2 sections).

This may be related to #1673.

Expected behavior

Executing db:cache:dump of a large application under Rails 5.1:

unknown             :   3936 ms
Sequence            :    320 ms
Primary Key         :   9551 ms
-------------------------------
total               :  13807 ms

Corresponding statement log

The results are grouped by query type (the string before the parenthesized time in the rails log) and are the average over multiple runs.

Actual behavior

Executing db:cache:dump of the same application under Rails 5.2:

tables              :    809 ms
views               :    504 ms
synonyms            :   1987 ms
Sequence            :   6270 ms
Primary Key         : 134574 ms
Column definitions  :  30425 ms
current schema      :      6 ms
table exists        :    181 ms
unknown             :      9 ms
-------------------------------
total               : 174765 ms

Corresponding statement log

This is over 12x slower than with Rails 5.1.

System configuration

Rails version: 5.1 / 5.2

Oracle enhanced adapter version: 1.8.2 / 5.2.2

Ruby version: jruby 9.1.14.0 (2.3.3) 2017-11-08 2176f24 Java HotSpot™ 64-Bit Server VM 25.66-b17 on 1.8.0_66-b17 +jit [darwin-x86_64]

Oracle Database version: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production

Final thoughts

As always a ton of thanks to you for looking at this and I’m sorry I couln’t provide an isolated performance test – I hope that comparing the database statements of the two log files will do the trick!

About this issue

  • Original URL
  • State: closed
  • Created 6 years ago
  • Comments: 39 (10 by maintainers)

Commits related to this issue

Most upvoted comments

Oracle enhanced adapter 5.2.3 has been released which should address this issue. Thanks for everyone who investigated and tested some test branches.

One possible reason is changing the execution plan may cause a longer elapsed time.

If you are using Oracle Database 12c Release 1, how about disabling optimizer_adaptive_features explained in these articles:

Since these parameters are changing in every database versions, I am not thinking about setting these parameters in Oracle enhanced adapter itself.

@yahonda Thank you for turning.

I’m using multiple activerecord versions at my gem CI

AR 5.2.0 + oracle-enhanced v5.2.2 build is very very slow, but It seems this issue was fixed at https://github.com/rsim/oracle-enhanced/issues/1720#issuecomment-409207938 (yahonda/oracle-enhanced@2dc2ef9)

Benchmark

c.f. https://github.com/sue445/index_shotgun/pull/48

Thank you.

Thanks for the testing everyone.

I have made several changes: Actually my environment does not get performance improvement by adding a search condition.

gem "activerecord-oracle_enhanced-adapter", github: 'yahonda/oracle-enhanced', branch: "diag1720_release52"

Please give it a try and let me know the result.

Thank you.

@yahonda thank you for taking a look at this. Using your branch, my findings were sadly similar to those of @InteNs - the indexes query takes ~6000ms each time, and runs for every table being dumped.

However, I found the further addition of:

- result = select_all(<<-SQL.strip.gsub(/\s+/, " "), "indexes", [bind_string("owner", owner), bind_string("owner", owner)])
+ result = select_all(<<-SQL.strip.gsub(/\s+/, " "), "indexes", [bind_string("owner", owner), bind_string("owner", owner), bind_string("table_name", table_name)])
    SELECT LOWER(i.table_name) AS table_name, LOWER(i.index_name) AS index_name, i.uniqueness,
      i.index_type, i.ityp_owner, i.ityp_name, i.parameters,
      LOWER(i.tablespace_name) AS tablespace_name,
      LOWER(c.column_name) AS column_name, e.column_expression,
      atc.virtual_column
    FROM all_indexes#{db_link} i
      JOIN all_ind_columns#{db_link} c ON c.index_name = i.index_name AND c.index_owner = i.owner
      LEFT OUTER JOIN all_ind_expressions#{db_link} e ON e.index_name = i.index_name AND
        e.index_owner = i.owner AND e.column_position = c.column_position
      LEFT OUTER JOIN all_tab_cols#{db_link} atc ON i.table_name = atc.table_name AND
        c.column_name = atc.column_name AND i.owner = atc.owner AND atc.hidden_column = 'NO'
    WHERE i.owner = :owner
       AND i.table_owner = :owner
+      AND i.table_name = :table_name
       AND NOT EXISTS (SELECT uc.index_name FROM all_constraints uc
        WHERE uc.index_name = i.index_name AND uc.owner = i.owner AND uc.constraint_type = 'P')
    ORDER BY i.index_name, c.column_position
  SQL

to the query reduced the execution time from ~6000ms to ~15ms - perhaps worth rolling in too? As far as I can see, because this query is no longer cached it needn’t get results for all indexes every time.

@yahonda running rails db:schema:dump on this branch results in utter slowness (compared to https://github.com/jlahtinen/oracle-enhanced/tree/optimize_schema_statement)

the main issue is retrieving indexes with the query as defined below.

  • This query gets executed multiple times during the schema dump
  • All these executions take more than 120.000 ms
  • Running this query through a database client also takes around 2 minutes.
  • the query takes around 1000 ms on @jlahtinen’s fork

edit:

rails db:schema:dump RAILS_ENV=production

  • query takes more than 5000 ms

  • our production database is oracle 12c

  • our test database is oracle 11g express

    • this is where we normally run our schema:dump for migrations
SELECT LOWER(i.table_name)      AS table_name,
       LOWER(i.index_name)      AS index_name,
       i.uniqueness,
       i.index_type,
       i.ityp_owner,
       i.ityp_name,
       i.parameters,
       LOWER(i.tablespace_name) AS tablespace_name,
       LOWER(c.column_name)     AS column_name,
       e.column_expression,
       atc.virtual_column
FROM all_indexes i
       JOIN all_ind_columns c ON c.index_name = i.index_name AND c.index_owner = i.owner
       LEFT OUTER JOIN all_ind_expressions e
         ON e.index_name = i.index_name AND e.index_owner = i.owner AND e.column_position = c.column_position
       LEFT OUTER JOIN all_tab_cols atc
         ON i.table_name = atc.table_name AND c.column_name = atc.column_name AND i.owner = atc.owner AND
            atc.hidden_column = 'NO'
WHERE i.owner = :owner
  AND i.table_owner = :owner
  AND NOT EXISTS(SELECT uc.index_name
                 FROM all_constraints uc
                 WHERE uc.index_name = i.index_name
                   AND uc.owner = i.owner
                   AND uc.constraint_type = 'P')
ORDER BY i.index_name, c.column_position

I was able to increase db:migration time a lot with https://github.com/jlahtinen/oracle-enhanced/tree/optimize_schema_statement

I used rule optimizer also, but left outer join increased performance from 25s to 1.5s in that modified query. It also seems like this query is used multiple times in 5.2 branch and not in 5.1 branch.

@yahonda maybe you are able to check if this is done correctly and merge it to your branches

It is likely due to execution plan change for this query https://github.com/rsim/oracle-enhanced/blob/fb1cbbf1498b452fa2fff32e8c3cd90c0d144363/lib/active_record/connection_adapters/oracle_enhanced_adapter.rb#L557-L565

Would you change each change to see if you see performance improvement.

  • Gather dictionary stats, which would require DBA privileges
SQL> exec dbms_stats.gather_dictionary_stats()
  • Update database.yml to use cursor_sharing: :force
  cursor_sharing: :force

Background:

Oracle enhanced adapter 5.2.0 #1498 introduces bind values for dictionary queries then default value of cursor_sharing changed from force to using the database instance value, likely exact.

However, to address #1678 Oracle enhanced adapter 5.2.1 reverted some of changes made #1498 to use sql literals. The query for primary key is one of them.

Thank you.