Speedup activerecord tests

[fatkodima]

Follow up to #47499 and #47510

This PR consists of 2 changes (commits):

Optimizing one of activerecord tests

I used https://github.com/y-yagi/minitest-test_profile to find the slowest tests. The slowest one (Finished in 227.415914s, 40.3534 runs/s, 136.6659 assertions/s.) took 10 seconds to run.

To reproduce:

$ cd activerecord
$ SEED=1 rake db:postgresql:rebuild postgresql:test TEST=test/cases/query_cache_test.rb TESTOPTS='-v --name="/test_query_caching_is_local_to_the_current_thread|test_cache_is_available_when_using_a_not_connected_connection/"'

Before

# Running:

QueryCacheTest#test_query_caching_is_local_to_the_current_thread = 0.11 s = .
QueryCacheTest#test_cache_is_available_when_using_a_not_connected_connection = 10.12 s = .

After

# Running:

QueryCacheTest#test_query_caching_is_local_to_the_current_thread = 0.10 s = .
QueryCacheTest#test_cache_is_available_when_using_a_not_connected_connection = 0.11 s = .

Disabling debug.log on CI

This change was introduced before (in #47499) but was reverted after (in #47537). It was mysterious why sqlite3_mem tests were started to fail, so we decided to just revert. Back then, I was able to reproduce that failure locally (unfortunately without a stable --seed, just running the tests enough times). When reverted, I ran tests 100 times and haven't seen a failure again. Now, I reintroduced that change and ran tests again for 100 times, and no failure! I saw recently some changes were merged on main that fixed some flaky behavior in tests (or something like that), so maybe that is relevant.

I also ran stackprof testing both changes.

$ CI=1 SEED=1 bundle exec stackprof run -- rake postgresql:test

Before (look at <======= marks)

TOTAL    (pct)     SAMPLES    (pct)     FRAME
     87430   (9.7%)       87429   (9.7%)     PG::Connection#exec_params
     23257   (2.6%)       23257   (2.6%)     IO#write  <=======
     15071   (1.7%)       15071   (1.7%)     (marking)
     13524   (1.5%)       13524   (1.5%)     (sweeping)
     11896   (1.3%)       11896   (1.3%)     IO#wait
     11112   (1.2%)       11112   (1.2%)     PG::Connection#exec_prepared
     10741   (1.2%)       10741   (1.2%)     Thread::Mutex#sleep  <=======
     10175   (1.1%)       10175   (1.1%)     BCrypt::Engine.__bc_crypt
      9380   (1.0%)        9380   (1.0%)     Thread#join
    347716  (38.5%)        7986   (0.9%)     Thread.handle_interrupt
      7694   (0.9%)        7694   (0.9%)     Kernel#sleep
      7492   (0.8%)        7492   (0.8%)     Regexp#===  <=======
    854767  (94.7%)        4563   (0.5%)     Array#each
      4190   (0.5%)        4190   (0.5%)     IO#stat
     67665   (7.5%)        4098   (0.5%)     ActiveRecord::LogSubscriber#sql  <=======
    430409  (47.7%)        3758   (0.4%)     ActiveRecord::ConnectionAdapters::AbstractAdapter#with_raw_connection
      3744   (0.4%)        3744   (0.4%)     Regexp#match?
      4666   (0.5%)        3657   (0.4%)     Concurrent::Collection::NonConcurrentMapBackend#[]
      3515   (0.4%)        3515   (0.4%)     Process.clock_gettime

After

     TOTAL    (pct)     SAMPLES    (pct)     FRAME
     93468  (11.3%)       93464  (11.3%)     PG::Connection#exec_params
     15307   (1.9%)       15307   (1.9%)     (marking)
     12371   (1.5%)       12371   (1.5%)     PG::Connection#exec_prepared
     12128   (1.5%)       12128   (1.5%)     (sweeping)
     11913   (1.4%)       11913   (1.4%)     IO#wait
     10165   (1.2%)       10165   (1.2%)     BCrypt::Engine.__bc_crypt
      8864   (1.1%)        8864   (1.1%)     Thread#join
      7614   (0.9%)        7614   (0.9%)     Kernel#sleep
    309268  (37.5%)        7277   (0.9%)     Thread.handle_interrupt
    761223  (92.3%)        3884   (0.5%)     Array#each
    459437  (55.7%)        3543   (0.4%)     ActiveRecord::ConnectionAdapters::AbstractAdapter#with_raw_connection
      3488   (0.4%)        3488   (0.4%)     Process.waitpid
      4173   (0.5%)        3365   (0.4%)     Concurrent::Collection::NonConcurrentMapBackend#[]
      3280   (0.4%)        3280   (0.4%)     Regexp#match?
      3177   (0.4%)        3177   (0.4%)     String#sub!
      3118   (0.4%)        3118   (0.4%)     String#match?
     36096   (4.4%)        2931   (0.4%)     Hash#each_value
      3688   (0.4%)        2928   (0.4%)     ActiveRecord::SchemaDumper#remove_prefix_and_suffix

Total execution time

Before: Finished in 263.680025s, 34.8035 runs/s, 117.8701 assertions/s.
After: Finished in 227.415914s, 40.3534 runs/s, 136.6659 assertions/s. (35 seconds less)

Additional

It is very easy to get the slowest tests in rspec by using a cli flag and it is possible for minitest, but using an external gem that I used. Also, there was recently a UX addition to the rails test runner to be able to filter test cases by lines (line ranges). Wdyt on adding a native ability to rails test runner to print the slowest tests?

[zzak]

@fatkodima @byroot How about to re-enable debug log on CI? I also wondered if we had the facility or wanted to retrieve coredumps in some cases.

[byroot]

?

[rafaelfranca]

He means this change https://github.com/rails/rails/pull/49030/files#diff-1080ad0e6eb23991c5d3ac5a71adc545f7977d47da5df19079e0502b2ed09628R26

We need a new environment variable to reanable it if we want to on CI.