Performance regression when creating records after update from rails 5.1 to rails 5.2

[InteNs]

Steps to reproduce

I've created the dump file: rails db:schema:cache:dump
I've enabled AR schema caching: config.active_record.use_schema_cache_dump = true
I know AR looks for the schema file and uses it because it throws expired errors when the schema dump was from another DB (on a different schema_version)

I'm also curious how to manage different databases (test, staging prod) that are on different schema_versions. the cache will be invalid etc.

I liked the old behaviour (where oracle adapter manages cache) better.

Expected behavior

Rails shouldn't be 3 times slower on 5.2

Actual behavior

AR is doing a lot of meta queries for column data.
the Rspec suite takes 3 times as long on rails 5.2 vs 5.1

I've made an album with the different caching behaviour in rails 5.1 and 5.2:
album
I thought this might be the most readable format for this.

My conclusion from these logs is that rails 5.2 with cache_dump is an improvement for the first call.
However the second call still does more queries than 5.1 and this slows down our test suite considerably.

System configuration

Rails version: 5.2.0.rc1

Oracle enhanced adapter version: 5.2.0.rc1

Ruby version: 2.4.1

Oracle Database version: 11g for test, 12c for prod

[yahonda]

Thanks for using Oracle enhanced adapter 5.2.0.rc1 before releasing GA versions.

Comparing performance by taking a look at screen shot is little bit harder for me. It would be appreciated if you provdide some sample applications / script that I and other contributors can execute and compare performances.

Also, Rails 5.2.0.rc2 has been released. It is helpful if you test with Rails 5.2.0.rc2.

rails/rails@v5.2.0.rc1...v5.2.0.rc2

Let me explain the background why Rails schema cache is chosen at #1490

I prefer to reduce Oracle enhanced adapter specific code and implementations. I would like to use Rails standard implementations. Schema cache is one of this. Rails is still heavily developed, especially Active Record is. To keep up supporting the latest version of Rails itself requires enough amount of developing.

I believe not having its Oracle enhanced adapter specific feature would help users, such as usage questions. If you would like to know how to use schema cache between Rails environments, I think you can get more wider information such as stackoverflow.com since this question should be generic for all Rails users.

Thank you.

[InteNs]

I understand removing this is a good thing for complexity but your compromising a lot of performance this way. I would appreciate keeping your specific implementation available for us that depend on the added performance.

Also I would think an adapter changing the caching implementation is perfectly reasonable if it can bring better performance or compatibility.

Please consider bringing this back and disabling it by default until rails caching is up to par.

[InteNs]

@yahonda I've made some test cases that show that creating records take about 3 to 4 times as long on rails 5.2 compared to 5.1.

here is the gist

I've also noticed that the main bottleneck is fetching primary keys, sometimes taking up to 2 seconds for the select statement.

I hope these scripts display the issue I am experiencing.
These are my test results:

5-1

BENCHMARK:
  1.260000   0.090000   1.350000 (  4.665202)

5-2

BENCHMARK:
  3.490000   0.310000   3.800000 ( 21.621645)

[yahonda]

Thanks for the proving useful test cases. Let me take a look at them. Thank you.

[yahonda]

I have made a diag commit to see if you see a performance improvement in 5.2.

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

Here is the background for this diag commit.

Running https://gist.github.com/InteNs/d01d387fc1472268b5189467c3c195bf#file-active_record_gem_spec_5_2-rb in my local environment and found these extra queries would have caused performance differences between 5.1 and 5.2.

D, [2018-04-12T12:30:24.662946 #8646] DEBUG -- :   Sequence (0.3ms)  select us.sequence_name from all_sequences us where us.sequence_owner = :owner and us.sequence_name = :sequence_name  [["owner", "ORACLE_ENHANCED"], ["sequence_name", "POSTS_SEQ"]]
D, [2018-04-12T12:30:24.663955 #8646] DEBUG -- :   Primary Key (0.7ms)  SELECT cc.column_name FROM all_constraints c, all_cons_columns cc WHERE c.owner = :owner AND c.table_name = :table_name AND c.constraint_type = 'P' AND cc.owner = c.owner AND cc.constraint_name = c.constraint_name  [["owner", "ORACLE_ENHANCED"], ["table_name", "POSTS"]]
D, [2018-04-12T12:30:24.664538 #8646] DEBUG -- :   Primary Key Trigger (0.4ms)  SELECT trigger_name FROM all_triggers WHERE owner = :owner AND trigger_name = :trigger_name AND table_owner = :owner AND table_name = :table_name AND status = 'ENABLED'  [["owner", "ORACLE_ENHANCED"], ["trigger_name", "POSTS_PKT"], ["owner", "ORACLE_ENHANCED"], ["table_name", "POSTS"]]

These queries are made here.

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

Line 431 in 6ed88c3

do_not_prefetch = !has_primary_key?(table_name, owner, desc_table_name, db_link) || has_primary_key_trigger?(table_name, owner, desc_table_name, db_link)

No other bundled database adapters - sqlite3, mysql2 and postgresql use prefetch primary key, then sequence name for the table may not be included in the schema cache, I guess.

[InteNs]

Thanks for the quick response and commit!

here's my results:
v1.8.2

BENCHMARK:
  1.520000   0.130000   1.650000 (  7.096358)

SQL (0.8ms)  INSERT INTO "POSTS" ("ID") VALUES (:a1)  [["id", 10003]]

diag1673_release52

BENCHMARK:
  1.970000   0.170000   2.140000 ( 12.530330)

next sequence value (1.1ms)  SELECT "POSTS_SEQ".NEXTVAL FROM dual
Post Create (0.9ms)  INSERT INTO "POSTS" ("ID") VALUES (:a1)  [["id", 10990]]

definitely an improvement over release52!

There is still a notable difference between v1.8.2 and diag1673_release52.

the benchmark is ~twice as fast on v1.8.2 now mainly due to next sequence queries.
This might just be a logging thing but i'm not sure.

[yahonda]

Thanks for the update. Glad to hear you are also getting better performance.

SELECT "POSTS_SEQ".NEXTVAL FROM dual statement executed in both cases - 1.8.2 and 5.2.0.

The difference is if the SELECT "POSTS_SEQ".NEXTVAL FROM dual is logged or not.
It was not logged before #1560, which changed the method to execute this SQL statement. I think SELECT "POSTS_SEQ".NEXTVAL FROM dual is the SQL statement and it needs to be logged.