Schema loading performance regression after update from rails 5.1 to rails 5.2

[sudoremo]

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(TM) 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!

[sudoremo]

I've now been able to isolate this issue with a script. It shows even more drastic numbers than the example above.

To use this script

1. Adapt the DB_CONFIG constant or provide the necessary environment variables

2. Run the script twice, once for 5.1 and once for 5.2:

   # Using rails 5.1.6 and enhanced adapter 1.8.2
   jruby oracle_enhanced_1720.rb
   
   # Using rails 5.2 and enhanced adapter 5.2.2
   NEW=true jruby oracle_enhanced_1720.rb

   This can also be run with MRI (you may need to add oci8 to the list of gems), but for some reason I was unable to get it to connect to our database so I made it for jRuby.

Results: Rails 5.1 / Adapter 1.8.2

BENCHMARK:
  8.270000   0.210000   8.480000 ( 13.275247)
.

Finished in 13.293265s, 0.0752 runs/s, 0.0000 assertions/s.

1 runs, 0 assertions, 0 failures, 0 errors, 0 skips
jruby oracle_enhanced_1720.rb  54.68s user 1.90s system 134% cpu 42.108 total

Total execution time: 42.108s Log

Results: Rails 5.2 / Adapter 5.2.2

BENCHMARK:
  8.820000   0.280000   9.100000 (136.128926)
.

Finished in 136.141032s, 0.0073 runs/s, 0.0000 assertions/s.

1 runs, 0 assertions, 0 failures, 0 errors, 0 skips
NEW=true jruby oracle_enhanced_1720.rb  55.83s user 1.93s system 28% cpu 3:21.29 total

Total execution time: 201.29s Log

Conclusion

Not only loading the model classes (that leads to structural queries) but also the migration takes way longer with Rails 5.2 than with Rails 5.1. This leads to extremely poor performance in our Rails 5.2 applications.

The total execution time is 4.7 times slower in 5.2 than in 5.1.

Thank you a lot for having a look at this 👍

[sudoremo]

To rule out an issue with Rails that is independent of the oracle enhanced adapter, I've also created a script for MySQL.

Results: Rails 5.1

BENCHMARK:
  3.290000   0.070000   3.360000 (  0.704586)
.

Finished in 0.725115s, 1.3791 runs/s, 0.0000 assertions/s.

1 runs, 0 assertions, 0 failures, 0 errors, 0 skips
jruby oracle_enhanced_1720_mysql.rb  48.22s user 1.72s system 352% cpu 14.170 total

Total execution time: 14.170s

Results: Rails 5.2

BENCHMARK:
  3.010000   0.090000   3.100000 (  0.680692)
.

Finished in 0.697151s, 1.4344 runs/s, 0.0000 assertions/s.

1 runs, 0 assertions, 0 failures, 0 errors, 0 skips
NEW=true jruby oracle_enhanced_1720_mysql.rb  59.73s user 2.17s system 363% cpu 17.014 total

Total execution time: 17.014s

Conclusion

• There is much less difference between 5.1 and 5.2.
• Both execution times are signifficantly shorter than with the oracle enhanced
  adapter (of course some of this difference may be because of the database and
  not due to the adapter). Oracle is 11x slower than MySQL.

[yahonda]

Thanks for providing test cases.

Would you upload the entire log files of Results: Rails 5.1 / Adapter 1.8.2 and Results: Rails 5.2 / Adapter 5.2.2

I'd like to know which statements taking time.

[sudoremo]

Thanks for your answer @yahonda. Sure, I've added links to the respective log files above, right after the total execution time.

The queries look very similar to me, i.e.:

5.1

Primary Key (3.0ms) SELECT cc.column_name FROM all_constraints c, all_cons_columns cc WHERE c.owner = 'RFRITZSCHE4' AND c.table_name = 'TABLE_19' AND c.constraint_type = 'P' AND cc.owner = c.owner AND cc.constraint_name = c.constraint_name

5.2

Primary Key (1948.0ms) SELECT cc.column_name FROM all_constraints c, all_cons_columns cc WHERE c.owner = 'RFRITZSCHE4' AND c.table_name = 'TABLE_19' AND c.constraint_type = 'P' AND cc.owner = c.owner AND cc.constraint_name = c.constraint_name

But for some reason, 5.2 is 650x slower for the same query. Is there maybe a general problem that affects performance in 5.2?

[yahonda]

It is likely due to execution plan change for this query

oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_adapter.rb

Lines 557 to 565 in fb1cbbf

	pks = select_values(<<-SQL.strip.gsub(/\s+/, " "), "Primary Key")
	SELECT cc.column_name
	FROM all_constraints#{db_link} c, all_cons_columns#{db_link} cc
	WHERE c.owner = '#{owner}'
	AND c.table_name = #{quote(desc_table_name)}
	AND c.constraint_type = 'P'
	AND cc.owner = c.owner
	AND cc.constraint_name = c.constraint_name
	SQL

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.

[sudoremo]

Thanks for your answer. Here the results:

• 5.2: New run without any changes: 152s
• 5.2: Run with cursor_sharing: :force: 90s
• 5.1: Run with cursor_sharing: :force: 13s
• 5.2: Run with cursor_sharing: :force and dictionary stats: 10s

Edit: Now I've run it again and 5.2 with both "settings" now takes 85s again.

[yahonda]

Thanks for testing. I'd like to request you to upload the log files for these tests.

* 5.2: Run with cursor_sharing: :force and dictionary stats: 10s

* Edit: Now I've run it again and 5.2 with both "settings" now takes 85s again.

Thank you.

[sudoremo]

Sure, I'll upload it as soon as possible. Wouldn't it be easier for you running the script yourself to avoid constant back and forth communication? I'm more than happy to run it for you though.

[yahonda]

Thanks. Actually, I did execute your script file before but unable to reproduce the slowness.

[sudoremo]

Ah ok. Sure, I'll be getting back to you asap.

[sudoremo]

Sorry for the delay. I've now performed the following sequence of actions:

1. Database user dropped and newly created

2. First script execution with forced cursor sharing
   Took 50s, 106s in total, Log

3. Gathering dictionary statistics

4. Second script execution with forced cursor sharing
   Took 16s, 47s in total, Log

5. Third script execution without forced cursor sharing:
   Took 147s, 220s in total, Log

6. Fourth script execution with forced cursor sharing again:
   Took 90s, 150s in total, Log

So the peculiar thing is that the run after turning off cursor sharing, but with cursor sharing, is very slow again.

Does this help? Thanks for looking into it.

[jlahtinen]

We are also experiencing performance problems now when upgrading to 5.2. We found that queries to Oracle data dictionary took at least 10 times more when using default optimizer mode compared to RULE based optimizer.

Maybe you should find out if those dictionary queries are the problem here also.

I changed all select queries accessing data dictionary with /*+ RULE */ hint in oracle-enhanced project and now our application is quite performant again.

Before doing this I just added exec "alter session set optimizer_mode=RULE" in jdbc_connection.rb after cursor sharing and all looked promising. I removed alter session before adding rule hints.

I do not know if this approach is good or not. More information about optimizer hints https://docs.oracle.com/cd/B10500_01/server.920/a96533/hintsref.htm#4991 At least that deprecation warning worries me.

[yahonda]

Thanks for the update and useful information. Let me create a branch to add rule hints for some of the queries for Oracle database dictionary to see if this issue resolves. As far as I remember rule hint has not been "supported" since 10g but there is a similar issue reported dbeaver/dbeaver#360 then I hope it would help ours.