Skip to content

Instantly share code, notes, and snippets.

@josh-works

josh-works/dev_notes_for_open_streetmap_test_harness.md

Last active April 19, 2024 00:33
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save josh-works/552c7db716372431d5b181f19ee36804 to your computer and use it in GitHub Desktop.
Save josh-works/552c7db716372431d5b181f19ee36804 to your computer and use it in GitHub Desktop.
Download ZIP
dev notes for OpenStreetMap test harness fix. 8 minutes -> 5 minutes
Raw
dev_notes_for_open_streetmap_test_harness.md

Utter this to anyone I've ever worked with:

Josh sometimes writes a lot/too much even. True or false?

They'll laugh. This is a normal amount of written output for my style. Anyway, here's my 'dev notes' for openstreetmap-website/pull/4708: Reduce test run time

Turn off logging durring testing, a few days ago

estimate 5% reduction in test run time

before supressing test logging:
Finished in 573.304009s, 2.9949 runs/s, 1744.7602 assertions/s.
# 9.55 min

Finished in 536.534444s, 3.2002 runs/s, 1864.3277 assertions/s.
# 8.94 min

something like:

# config/environments/test.rb ?
config.after_initialize do
  ActiveRecord::Base.logger = nil
end

didn't work

next, this

--log_to_stdout=false

perhaps bundle exec rails test:all --log_to_stdout=false

Or

# test/test_helper.rb
puts ActiveRecord::Base.logger.level
puts "setting base logger level to 1"
ActiveRecord::Base.logger.level = 1 # or Logger::INFO
puts ActiveRecord::Base.logger

nope, ActiveRecord::Base.logger seems available.

/Users/joshthompson/software_projects/openstreetmap-website/test/test_helper.rb:39:in `<main>': undefined method `level' for nil:NilClass (NoMethodError)

puts ActiveRecord::Base.logger.level

Lets try to hit a pry in a test file. Add pry to the gemfile, run b rails test test/models/message_test.rb

    22: def test_invalid_send_recipient
 => 23:   require "pry"; binding.pry
    24:   message = create(:message, :unread)
    25:   message.sender = nil
    26:   message.recipient = nil
    27:   assert_not_predicate message, :valid?
    28:
    29:   assert_raise(ActiveRecord::RecordNotFound) { User.find(0) }
    30:   message.from_user_id = 0
    31:   message.to_user_id = 0
    32:   assert_raise(ActiveRecord::RecordInvalid) { message.save! }
    33: end

[1] pry(#<MessageTest>)> ActiveRecord::Base.logger
=> #<ActiveSupport::BroadcastLogger:0x000000010aa2aa48
 @broadcasts=
  [#<ActiveSupport::Logger:0x000000010e148340
    @default_formatter=#<Logger::Formatter:0x000000010b5333e0 @datetime_format=nil>,
    @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x000000010aa61200 @datetime_format=nil, @thread_key="activesupport_tagged_logging_tags:25260">,
    @level=0,
    @local_level_key=:logger_thread_safe_level_25020,
    @logdev=
     #<Logger::LogDevice:0x000000010e14c0d0
      @binmode=false,
      @dev=#<File:/Users/joshthompson/software_projects/openstreetmap-website/log/test.log>,
      @filename="/Users/joshthompson/software_projects/openstreetmap-website/log/test.log",
      @mon_data=#<Monitor:0x000000010b532648>,
      @mon_data_owner_object_id=10460,
      @shift_age=1,
      @shift_period_suffix="%Y%m%d",
      @shift_size=104857600>,
    @progname=nil>],
 @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x000000010aa61200 @datetime_format=nil, @thread_key="activesupport_tagged_logging_tags:25260">,
 @progname="Broadcast">
[2] pry(#<MessageTest>)>

Well, there's a logger.

Wonder if we can make it nil:

[2] pry(#<MessageTest>)> ActiveRecord::Base.logger = nil
=> nil
[3] pry(#<MessageTest>)> ActiveRecord::Base.logger
=> nil
[4] pry(#<MessageTest>)>

Turning off logging, March 29, 2024

en route to cripple creak

ActiveRecord::Base.logger = nil

Ah, OK, got it, this worked:

# config/environments/test.rb
config.log_level = :warn

Tests are running almost completely without logs, and it turns out, the logs that ARE coming out are helpful. Here's the full logs:

(wikipedia) Authentication failure! invalid_credentials encountered.
(github) Authentication failure! invalid_credentials encountered.
(facebook) Authentication failure! invalid_credentials encountered.
(google) Authentication failure! connection_failed encountered.
(openid) Authentication failure! connection_failed encountered.
(google) Authentication failure! invalid_credentials encountered.
(microsoft) Authentication failure! connection_failed encountered.
(wikipedia) Authentication failure! connection_failed encountered.
(facebook) Authentication failure! connection_failed encountered.
(openid) Authentication failure! invalid_credentials encountered.
(microsoft) Authentication failure! invalid_credentials encountered.
(github) Authentication failure! connection_failed encountered.
(wikipedia) Authentication failure! connection_failed encountered.
(facebook) Authentication failure! connection_failed encountered.
(microsoft) Authentication failure! connection_failed encountered.
(github) Authentication failure! connection_failed encountered.
(google) Authentication failure! connection_failed encountered.
(openid) Authentication failure! connection_failed encountered.

ActionController::RoutingError (No route matches [GET] "/api/0.6/changeset/1843/close"):

config/initializers/cors.rb:9:in `call'
test/controllers/api/changesets_controller_test.rb:457:in `test_close_method_invalid'

ActionController::RoutingError (No route matches [POST] "/api/0.6/changeset/1843/close"):

config/initializers/cors.rb:9:in `call'
test/controllers/api/changesets_controller_test.rb:461:in `test_close_method_invalid'

ActionController::RoutingError (No route matches [GET] "/api/0.6/changeset/create"):

config/initializers/cors.rb:9:in `call'
test/controllers/api/changesets_controller_test.rb:138:in `test_create_wrong_method'

ActionController::RoutingError (No route matches [POST] "/api/0.6/changeset/create"):

config/initializers/cors.rb:9:in `call'
test/controllers/api/changesets_controller_test.rb:142:in `test_create_wrong_method'

So, that will lead us to our next fix, 'run tests without internet', because this sure looks like a 'we tried to make a network call and was unsuccessful' errors. There was lots of red, which might also account for the 'fast' test time.

If there are any failures, we'll wrap those calls in VCR, and that'll do more time savings things.

I'm so curious to know how the tests compare, but I'm running them on battery right now, so there could both be an improvement, and the clock time on this laptop will go up, so i'll also run the tests with logging enabled, or i'll plug this in.

i'll prob plug it in. Whatever it is, i'll do a before and after, logging enabled/disabled, with the laptop in the same state.

...

Finished in 361.787146s, 4.4805 runs/s, 2763.9705 assertions/s
# 6 minutes flat seems like too big of an improvement

6 minutes flat seems like too big of an improvement. Also, slightly different counting, I could have attended to a different output - this was minitests self-reported timing, but I it doesn't include the time it takes for at least some of the app to boot, so I should be gathering the output of the time command. Here's the full thing:

Finished in 361.787146s, 4.4805 runs/s, 2763.9705 assertions/s.
# minitest's self-reported info. They're 10 seconds apart, 361 seconds, vs. time's multi-threaded nonsense?
1621 runs, 999969 assertions, 1 failures, 13 errors, 0 skips
[...]
bundle exec rails test  1811.14s user 163.94s system 524% cpu 6:16.87 total
# this is the 'time' command output

now I'm getting confused by output, possible multi-threading, but lemme just re-run stuff a few times. I still think suppressing logging is the VERY right move!

If the time savings WAS because the quick timeouts, that means i'll soak another TONS of speed improvement from VCR'ifying this. Gonna be GOAT if I quickly drop OSM's Rails test harness run time by half or more. Cool/fun flex

Re-running. Absolutely seeing the logs suppressed, I'd wanna turn them back on for diagnostics, when doing more profiling, PERHAPS.

Lots of errors like:

....E

Error:
TraceTest#test_import_handles_bz2:
NoMethodError: undefined method `info' for nil:NilClass
    app/models/trace.rb:202:in `import'
    test/models/trace_test.rb:231:in `test_import_handles_bz2'

restarting, having some other issues with the machine.

tail -f log/test.log # in one tab
time b rails test:all # in another tab

Perfect, this is working exactly as I hope. 😀. Logs are off. benchmarking fairly now.

Plugged in, fresh restart, nothing much happening on the laptop, I hear the fan turning on and running hard. The wifi is working, looks like less errors, but it was deff a clue.

# logging off, wifi on
bundle exec rails test:all  1971.10s user 207.71s system 571% cpu 6:21.01 total


# logging on, wifi on
bundle exec rails test:all  2022.70s user 222.81s system 579% cpu 6:27.51 total

# logging off, wifi off

wc -l log/test.log => 390k lines

re-running tests, just for fun. laptop cooled down and fan turned down. otherwise not touching anything.

also, would running tests while tailing the dev log slow anything down? Should I be doing like 'lines of logs generated per second'?

OK, finished. From an empty log, a single test run generates 27k lines:

$ wc -l log/test.log

=> 27016 log/test.log

Finished in 360.123669s, 4.7678 runs/s, 2777.5903 assertions/s.
1717 runs, 1000276 assertions, 1 failures, 13 errors, 0 skips

bundle exec rails test:all  1981.40s user 206.00s system 589% cpu 6:11.17 total

372 seconds, 27k lines of code, testing generates: 72 lines of logs, per second.

Again:

bundle exec rails test:all  1968.27s user 198.61s system 612% cpu 5:53.56 total

They also seem flaky. Hm.

  • Investigate flaky tests.

Error:
UserHelperTest#test_user_image_sizes_avatar:
LoadError: Could not open library 'vips.42': dlopen(vips.42, 0x0005): tried: 'vips.42' (no such file), '/System/Volumes/Preboot/Cryptexes/OSvips.42' (no such file), '/usr/lib/vips.42' (no such file, not in dyld cache), 'vips.42' (no such file).
Could not open library 'libvips.42.dylib': dlopen(libvips.42.dylib, 0x0005): tried: 'libvips.42.dylib' (no such file), '/System/Volumes/Preboot/Cryptexes/OSlibvips.42.dylib' (no such file), '/usr/lib/libvips.42.dylib' (no such file, not in dyld cache), 'libvips.42.dylib' (no such file).
Searched in <system library path>, /usr/lib, /usr/local/lib, /opt/local/lib
    test/helpers/user_helper_test.rb:91:in `test_user_image_sizes_avatar'

bin/rails test test/models/trace_test.rb:252

Error:
TraceTest#test_import_handles_plain_with_bom:
NoMethodError: undefined method `info' for nil:NilClass
    app/models/trace.rb:202:in `import'
    test/models/trace_test.rb:247:in `test_import_handles_plain_with_bom'

Across these runs, I see lots of flakey

bundle exec rails test:all  1986.73s user 212.35s system 589% cpu 6:13.02 total

logging off

changing from

config.log_level = :info

to:

config.log_level = :warn

Running 1717 tests in parallel using 4 processes

no logs:

Finished in 384.500082s, 4.4655 runs/s, 2601.4975 assertions/s.
1717 runs, 1000276 assertions, 1 failures, 13 errors, 0 skips

bundle exec rails test:all  2033.88s user 220.23s system 569% cpu 6:35.83 total

Doesn't seem vastly faster. technically is slower than the last run, when they were slow, but that was also full of flaky tests.

logs are mostly:

(microsoft) Authentication failure! connection_failed encountered.
(wikipedia) Authentication failure! connection_failed encountered.
(facebook) Authentication failure! connection_failed encountered.
(openid) Authentication failure! invalid_credentials encountered.
(github) Authentication failure! invalid_credentials encountered.
(github) Authentication failure! connection_failed encountered.
(wikipedia) Authentication failure! invalid_credentials encountered.
(facebook) Authentication failure! invalid_credentials encountered.
(microsoft) Authentication failure! invalid_credentials encountered.
(openid) Authentication failure! connection_failed encountered.
(google) Authentication failure! connection_failed encountered.
(google) Authentication failure! invalid_credentials encountered.

Logs off still seems hit or miss. Maybe it's a 6% improvement, but times are not reliable enough to be sure, yet

Turning off wifi

There's no VCR in the gemfile, I'll add it and ask it to monitor connections

so far it looks like one error:

[Screenshot Image]: /Users/joshthompson/software_projects/openstreetmap-website/tmp/screenshots/failures_test_externally_redirect_when_contributor_terms_declined.png
E

Error:
UserSignupTest#test_externally_redirect_when_contributor_terms_declined:
Selenium::WebDriver::Error::UnknownError: Reached error page: about:neterror?e=dnsNotFound&u=https%3A//wiki.openstreetmap.org/wiki/Contributor_Terms_Declined&c=UTF-8&d=We%20can%E2%80%99t%20connect%20to%20the%20server%20at%20wiki.openstreetmap.org.
    test/system/user_signup_test.rb:28:in `block in <class:UserSignupTest>'

OK, gem installed vcr, wifi off, lots of errors, configured VCR with:

# test/test_helper.rb
VCR.configure do |config|
  config.cassette_library_dir = "fixtures/vcr_cassettes"
  config.hook_into :webmock
end

and it's throwing lots of warnings, i'm not handling any of them

In a single test run, I've got 192 instances of

RuntimeError: Neutered Exception VCR::Errors::UnhandledHTTPRequestError

and that could be losing a lot of time.

Thanks to https://stackoverflow.com/questions/21114231/how-to-record-all-requests-using-vcr, I'll add:

VCR.configure do |vcr|
  vcr.cassette_library_dir = "fixtures/vcr_cassettes"
  vcr.hook_into :webmock

  vcr.before_http_request do |request|
    puts request
    require "pry"; binding.pry
    VCR.insert_cassette("hithere") 
  end

  vcr.after_http_request do |request|
    VCR.eject_cassette
  end
end

Re-running.

Meh, I think this is the right way, I remember doing this work for openunit and something like this working. It was suggested by Chris, maybe I should rejoin the slack.

Tuesday, April 2, 2024

I think run a spec that deff hits vcr error

FIX LIKE HELL

first fix in a file for one spec

VCR.configure do |vcr|
  vcr.cassette_library_dir = "fixtures/vcr_cassettes"
  vcr.hook_into :webmock
  vcr.ignore_localhost = true
end

Ignoring localhost, this runs clean:

test/system/user_signup_test.rb

bundle exec rails test test:all  1791.49s user 137.68s system 576% cpu 5:34.37 total

hm. now testing with lots of diagnostics. Feels like maybe the entire repo runs cleanly without any external calls?

Friday, April 12, 2024

It basically does [run cleanly without wifi], there's one probably minor selenium error:

 time b rails test test/system/user_signup_test.rb
2024-04-12 13:44:18 INFO Selenium [:logger_info] Details on how to use and modify Selenium logger:
  https://selenium.dev/documentation/webdriver/troubleshooting/logging

2024-04-12 13:44:18 WARN Selenium [:selenium_manager] Problem reading geckodriver versions: error sending request for url (https://raw.githubusercontent.com/SeleniumHQ/selenium/trunk/common/geckodriver/geckodriver-support.json): error trying to connect: dns error: failed to lookup address information: nodename nor servname provided, or not known. Using latest geckodriver version
2024-04-12 13:44:18 WARN Selenium [:selenium_manager] Exception managing firefox: error sending request for url (https://github.com/mozilla/geckodriver/releases/latest): error trying to connect: dns error: failed to lookup address information: nodename nor servname provided, or not known
2024-04-12 13:44:18 WARN Selenium [:selenium_manager] Error sending stats to Plausible: error sending request for url (https://plausible.io/api/event): error trying to connect: dns error: failed to lookup address information: nodename nor servname provided, or not known
Running 2 tests in a single process (parallelization threshold is 50)
Run options: --seed 10701

# Running:

.[Screenshot Image]: /Users/joshthompson/software_projects/openstreetmap-website/tmp/screenshots/failures_test_externally_redirect_when_contributor_terms_declined.png
E

Error:
UserSignupTest#test_externally_redirect_when_contributor_terms_declined:
Selenium::WebDriver::Error::UnknownError: Reached error page: about:neterror?e=dnsNotFound&u=https%3A//wiki.openstreetmap.org/wiki/Contributor_Terms_Declined&c=UTF-8&d=We%20can%E2%80%99t%20connect%20to%20the%20server%20at%20wiki.openstreetmap.org.
    test/system/user_signup_test.rb:28:in `block in <class:UserSignupTest>'


bin/rails test test/system/user_signup_test.rb:12



Finished in 18.837959s, 0.1062 runs/s, 0.1062 assertions/s.
2 runs, 2 assertions, 0 failures, 1 errors, 0 skips
Coverage report generated for Unit Tests to /Users/joshthompson/software_projects/openstreetmap-website/coverage. 1339 / 8040 LOC (16.65%) covered.
Lcov style coverage report generated for Unit Tests to coverage/lcov.info
bundle exec rails test test/system/user_signup_test.rb  34.84s user 11.62s system 124% cpu 37.441 total

Now, it's taking a while to boot the app. Since it's parallelized, as well, across threads, savings might magnify.

Running a single test, with a single assertion, takes 18 seconds per thread to boot? But integration/selenium/headless chrome tests are meeeeeeega slow, so... I have a thought that I'm going to answer:

  1. can I split integration tests into their own process so they can be run separately from everything else?
  2. If I can speed up the app boot process by half (lets say it takes 30 seconds to boot, .1 second to run a spec file with 100 specs, and I can make that run in 15 seconds + .1) how does that spread to other threads. Linearally or non-linearly, b/c parallelization gets us stuff like:
34.84s user 11.62s system 124% cpu 37.441 total

If you added 34.9 + 11.5 that's 47, not 37. Anyway, lets run a non-headless-browser test.

Picking a different model spec, sorta at random:

time b rails test test/models/note_comment_test.rb

I think it's useful to watch the output, in real time, in the terminal. The timing is distinctive. I also re-enable logging, because I'm interested in what looks like database start-up time. All of the DB statements in the logs, and there's a lot, happen very quickly after a long, slow startup. Back to the startup, in test_helper.rb.

Also, in support of the idea of logging being disabled, once all the startup happened and the tests were getting run, HUNDREDS of lines of output happened in a brief moment. I could see turning that off being useful, esp when more than a few tests are being run. meh.

Gonna "sprinkle more timing statements" throughout.

OK, still not able to get closer to app/boot. All the statements I'm adding are still firing in the last 1/10th of a second of the test run time, seemingly. 30 seconds to boot, then everything all at once.

OK what?

bundle exec rails test  128.40s user 21.47s system 239% cpu 1:02.51 total

1 minute and two seconds

total. That cannot be right. I note that I broke some of the tests by a puts statement somewhere there shouldn't have been:

bin/rails test test/controllers/changesets_controller_test.rb:485

E

Error:
ChangesetsControllerTest#test_index_bbox:
NoMethodError: undefined method `puts=' for #<User email: nil, id: nil, pass_crypt: nil, creation_time: nil, display_name: "", data_public: false, description: "", home_lat: nil, home_lon: nil, home_zoom: 3, pass_salt: nil, email_valid: false, new_email: nil, creation_ip: nil, languages: nil, status: "pending", terms_agreed: nil, consider_pd: false, auth_uid: nil, preferred_editor: nil, terms_seen: false, description_format: "markdown", changesets_count: 0, traces_count: 0, diary_entries_count: 0, image_use_gravatar: false, auth_provider: nil, home_tile: nil, tou_agreed: nil>
    test/controllers/changesets_controller_test.rb:98:in `test_index_bbox'

But I let the test harness run anyway, and am surprised to see it done so fast. WIFI is off.

This would be a 7 minute run time to a 1 minute run time, that's a speed improvement of like 80%? 1/7th of something is only a bit bigger than a tenth.

"if your tests take an hour right now, imagine if they ran in 6 minutes"

"if your tests take ten minutes, imagine them running in one. It's difficult to imagine, you don't have to. Imagine if a 7 minute test harness runs in one minute. Or a 20 minute test harness running in twelve."

wtf.

I'll pick up investigating "puts" soon.

Sunday April 14

Investigating the 'puts' statement more - tests were running super fast when every one that called a 'user' broke instantly.

A 6 minute test run became a 1 minute test run, and only a few tests failed.

Finished in 49.236064s, 32.9230 runs/s, 20111.2745 assertions/s.
1621 runs, 990200 assertions, 1 failures, 885 errors, 0 skips

885 errors is more than a few, I think this is the wrong direction...

I'm going to look at the tests that fail, and see if it's because some big slow process that needs to happen just doesn't even get fired. It's likely not that the 'user' object is slow to create, it's that the tests do a lot.

When I remove the puts statement, the tests return, go slow, but no failures.

Finished in 403.468365s, 4.0177 runs/s, 2478.4669 assertions/s.
1621 runs, 999983 assertions, 0 failures, 1 errors, 0 skips

bundle exec rails test  1768.87s user 192.28s system 473% cpu 6:53.81 total

Wednesday, April 17, 2024

Dropping back to a 'benchmarking' POV, I still wanna investigate that the tests finished in a single minute when I broke the 'user' factory.

I can figure it out, but as I started thinking about it, I could think of a few different approaches. I decided to check the logs again (turned them on, tailed the logs to watch the output) and keep puts ing things, and sorta 'streaming' the output. turn the log_level to :info, in one visible terminal tab tail log/test.log, in another tab do time bundle exec rails test:all. There's probably a minitest -verbose mode, too. I'm curious to know what tests are getting run. I can infer from the test output, sometimes directly, but like...test/models? test/controllers? test/system? Does the pace of once move at the exact same as the pace as the other?

Should I be running this in single-threaded mode, to gather a different slice of data? I assume four threads are running and the logs are getting mixed together...??? is that fair?

re-listening to the 'code with jason' podcast episode, super topical (duh)

Re-ran the test suite out of curiosity, while typing the above, listening to the podcast.

here's breaking the user factory:

FactoryBot.define do
  factory :user do
    puts { "making user via a factory" } # add this
    sequence(:email) { |n| "user#{n}@example.com" }

Oh, wanted to profile. Here's assertions per second for total suite:

assertions per second

Finished in 523.000911s, 3.2830 runs/s, 1912.5971 assertions/s.
1717 runs, 1000290 assertions, 0 failures, 1 errors, 0 skips
bundle exec rails test:all  2098.49s user 296.97s system 449% cpu 8:52.47 total

let_it_be as a strategy

If it indeed turns out that creating a user (and not the REST of the test predicated upon the user model existing, bc I didn't see much db traffic in the logs) then I could use let_it_be as a strategy, or maybe it's already been done. Should at least test it, so I know how, if it's not been done.

...

breaking the user create BLOWS UP the tests at the beginning, before a single assertion, then the assertions run fast as fuck.

Lots of other tests are also riiiiiiiping by, wow. All w/undef method puts=. Lol. look at this now:

Finished in 45.617334s, 37.6392 runs/s, 21706.6609 assertions/s.
1717 runs, 990200 assertions, 1 failures, 981 errors, 0 skips
bundle exec rails test:all  132.18s user 19.57s system 271% cpu 55.840 total

55 seconds total. 22,000 assertions/sec. lol. The last count was 2,400 assertions/second.

THERE is my 10x improvement that I want.

OK, did this:

test/factories/user.rb
FactoryBot.define do
  factory :user do
    # puts { "making user via a factory" } # this was breaking the `user` setup
    sequence(:email) { |n| p "hi"; "user#{n}@example.com" } # so I snuck it in here
    sequence(:display_name) { |n| "User #{n}" }

Now I can see exactly how many of the times this user object is being called, vs when it's created instantly, and for som reason IT IS A HUGE DIFFERENCE!

I can see hi streaming bye, and the tests seem to proceed as normal, at a normal (slow) speed.

I'm basically going down the user model, seeing if I can make any aspect of it faster/break it differently.

Finished in 249.807509s, 6.8733 runs/s, 3991.1771 assertions/s.
1717 runs, 997026 assertions, 400 failures, 35 errors, 0 skips
Coverage report generated for Minitest, Minitest-0, Minitest-1, Minitest-2, Minitest-3 to /Users/joshthompson/software_projects/openstreetmap-website/coverage. 5021 / 6758 LOC (74.3%) covered.
Lcov style coverage report generated for Minitest, Minitest-0, Minitest-1, Minitest-2, Minitest-3 to coverage/lcov.info
bundle exec rails test:all  597.63s user 161.30s system 289% cpu 4:21.84 total

Remember, our goal is something like 22k assertions/second, we either don't need to be calling this user constantly, we could/should stub it out.

I noticed that 'breaking' the password digest function might have helped.

FactoryBot.define do
  factory :user do
    # puts { "making user via a factory" }
    sequence(:email) { |n| p "fabbing #{"user#{n}@example.com"}"; "user#{n}@example.com" }
    sequence(:display_name) { |n| "User #{n}" }
    # pass_crypt { PasswordHash.create("test").first }
    pass_crypt { "randomlongenoughstringthatmightbegoodenoughbutprobablyisnt" }

less tests broke differently, and the tests were certainly faster.

now putting diff stuff:

FactoryBot.define do
  factory :user do
    # puts { "making user via a factory" }
    sequence(:email) { |n| p PasswordHash.create("test").first; "user#{n}@example.com" }
    sequence(:display_name) { |n| "User #{n}" }
    # pass_crypt { PasswordHash.create("test").first }
    pass_crypt { "randomlongenoughstringthatmightbegoodenoughbutprobablyisnt" }

looking way better, way faster

Still lots of errors, it's generating output like this:

"$argon2id$v=19$m=65536,t=3,p=4$M+oP6KQOdFLDeiYa/gbzAg$pULNwXgKt2sEmTxMXxt298skEqc8MjnPwGsk075jLrk"
"$argon2id$v=19$m=65536,t=3,p=4$MWk3F1jq8OGs8m1KADSKzQ$97iChQ0pI7ZhdKWvK2zuALdl6vr1cko9YneceBZ0SRY"
"$argon2id$v=19$m=65536,t=3,p=4$I6joRKGjBBDFUkDVTGl3Hw$Mm7HBWpQiA8zw0y9DlGScJsAZWLEpEYP/vwyYOCQgXo"
"$argon2id$v=19$m=65536,t=3,p=4$3W1VtIzJn00BkJjIbi7L9Q$jSrBc7co66BsfTLINrDjPMwHfmdH2WtXRYvC8qw8b5A"
"$argon2id$v=19$m=65536,t=3,p=4$1QCD2+t4UuM1awxraePirQ$iQp7Rf1NskAbIAWzTv5NBdtiSR+JzuGwk2sJUQWbLc0"
"$argon2id$v=19$m=65536,t=3,p=4$Sm2M0daauln/R67Dc2NNCQ$zo5gMtLEGSUZy1SPsGc2rnlPsUPtW11w4SZHNuKloH4"
"$argon2id$v=19$m=65536,t=3,p=4$gHbAIYV/n1rLO+ICu61fAQ$n++ouqaI35kxerp6woJMjb3xJS+7ALUa6h7zM5eNNeM"
F

Failure:
CompressedRequestsTest#test_deflate_compression [test/integration/compressed_requests_test.rb:144]:
can't upload a deflate compressed diff to changeset: Couldn't authenticate you


bin/rails test test/integration/compressed_requests_test.rb:103

these tests ran... i don't know, it didn't seem super fast. not even 4k/second, maybe slower. astonishingly this user seems to be getting created for nearly every single test. Between almost every single dot is the output of the hash algo


"$argon2id$v=19$m=65536,t=3,p=4$vWtan2jFeA3f4rbJwWyhtw$75qQbYDqh2gYxrwMAKyxAINp1fcfkZPFItODrfohp8k"
.."$argon2id$v=19$m=65536,t=3,p=4$oXqN74bN0idbjpkbq6oDBQ$k9F4+zFH9pdnFadB3VSkWytNGrf0GbvBAP2JSxNrN3Y"
"$argon2id$v=19$m=65536,t=3,p=4$RCBBM812fK+E/xa724/2zg$hCAQpbFuxVeyM+0KJ1pU466Z6H08zc/Agye15e+q/HQ"
."$argon2id$v=19$m=65536,t=3,p=4$5jgVw2KYm9ZAxN5ON1SqwQ$tJZhNbizNPiYcPFzPMiobNMue5UdtnTGb83YUWtE2m0"
."$argon2id$v=19$m=65536,t=3,p=4$IbJ/cU1DtFTDkZMZPWxJzQ$hAYZM8jrraCVk1B6E2RMMvF+WXRjKCIQ/NxJT5RYD54"
"$argon2id$v=19$m=65536,t=3,p=4$fHFQ0EZvQOc0yGhdePAxZw$nhSJ7uKYRY92MAqNuM/iJlb2q3xdu2Mh1h2N3KsFSbs"
."$argon2id$v=19$m=65536,t=3,p=4$qNbUT/jZjAUVp8Ho06XkvA$x1NbpCL77g/m3jUrgOcU9TSey1UZCaLxKTDSwDb1cuM"

yeah, this was 2100 assertions/second. regular slow.

So lets pop that magic string into the pass_crypt method, see if it helps.

FactoryBot.define do
  factory :user do
    sequence(:email) { |n| p "user#{n}@example.com"; "user#{n}@example.com" }
    sequence(:display_name) { |n| "User #{n}" }
    # pass_crypt { PasswordHash.create("test").first }
    pass_crypt { "$argon2id$v=19$m=65536,t=3,p=4$M+oP6KQOdFLDeiYa/gbzAg$pULNwXgKt2sEmTxMXxt298skEqc8MjnPwGsk075jLrk" }

So, the above bypasses PasswordHash.create completely, in a likely test-passing way, it's looking much faster already.

Lol. I'm feeling it. Since you can see the users increment you can see how the different threads are interacting, too:

"user109@example.com"
"user146@example.com"
"user120@example.com"
"user147@example.com"
"user121@example.com"
"user148@example.com"
"user122@example.com"
"user149@example.com"
"user123@example.com"
"user150@example.com"
"user124@example.com"
"user125@example.com"
"user126@example.com"
"user127@example.com"
."user114@example.com"
"user115@example.com"
."user110@example.com"
"user111@example.com"
.."user151@example.com"
."user152@example.com"
"user128@example.com"
"user129@example.com"
."user112@example.com"
"user113@example.com"
."user116@example.com"
"user117@example.com"
"user118@example.com"

siiiick this PR just got better.

This also means I'll be able to infer how many total users are created across all threads.

OK, here's the output:

Finished in 279.699456s, 6.1387 runs/s, 3576.3030 assertions/s.
1717 runs, 1000290 assertions, 0 failures, 1 errors, 0 skips
bundle exec rails test:all  932.26s user 183.99s system 381% cpu 4:52.67 total

Gonna update the PR. This will possibly fail a linter.

Updated the PR, going to stop here for now.

When I come back, I want to investigate via testprof https://test-prof.evilmartians.io/, the https://test-prof.evilmartians.io/profilers/event_prof output

I'll install it and run it real quick, as I wait for a maintainer to approve the Github Actions run.

[...]

So, add the gemfile, and run it with:

time b rails test:all --event-prof='sql.active_record,perform.active_job,factory.create'

doesn't work, nor does time b rails test:all --event-prof='factory.create'

lets try the environment variable option:

EVENT_PROF='sql.active_record'

can't get it to run. gonna take a walk for now, made great progress today. Will figure out how to get test-prof working, I'm still captivated by the 22k assertions/second by instantly setting up a user, leading to a 1 minute run time.

mm, it runs so clean right now. No further changes, but now down to 4:147, 4055 assertions/second. It fluctuates, test run to test run, but this is nice to see it go so fast.

Lets make it go faster. Again, breaking the tests by breaking the 'user' factory, so it fails as soon as build(:user) is called...

Finished in 42.813849s, 40.1038 runs/s, 23128.0304 assertions/s.
1717 runs, 990200 assertions, 1 failures, 981 errors, 0 skips
bundle exec rails test:all  126.96s user 19.92s system 278% cpu 52.768 total

52 seconds. 23,000 assertions/second. delicious.

okay, did some quick find-and-replace magic on the user, to go from create(:user) to build_stubbed(:user). Obviously it won't work everywhere, but I wonder what the patterns are across where it does/doesnt.

I did a test refactor of a single test file, the blind find/replace worked for some, but caused some to fail with an error like:

Error:
UserTest#test_active:
ActiveRecord::RecordNotFound: Couldn't find User with 'id'=1035 [WHERE "users"."status" IN ($1, $2)]
    test/models/user_test.rb:222:in `test_active'

checks out, as the whole point of build_stubbed is to not make a db call.

So, by tracking all these errors, I might know exactly where of the tests require having an underlying db object.

re-running tests, I'm curious obv about the test time.

I register a prediction that it'll be faster. I would not be surprised if the error count changed from 800 to... less.

I'd love it to be like 100 remaining errors (I might fix all of them manually), and that would soak speed improvements...

Results are in...

Finished in 197.169437s, 8.7082 runs/s, 5045.8936 assertions/s.
1717 runs, 994896 assertions, 253 failures, 227 errors, 0 skips

bundle exec rails test:all  533.64s user 124.35s system 316% cpu 3:27.59 total

3:27 total is GREAT, and the error count is down by a lot. this COULD be worth fixing, I prob won't have to do quite each of them manually.

I expect the speed improvement will not get larger or smaller as I fix these issues.

Looks like the tests that most wanted create was controller tests, for starters, so re-doing the find-and-replace to exclude all controller tests. 274 results remaining or something, but still lots of errors.

the speed improvement will be smaller now, too.

Seeing obvious errors like

E

Error:
CompressedRequestsTest#test_invalid_compression:
ActiveRecord::InvalidForeignKey: PG::ForeignKeyViolation: ERROR:  insert or update on table "changesets" violates foreign key constraint "changesets_user_id_fkey"
DETAIL:  Key (user_id)=(1018) is not present in table "users".

    test/integration/compressed_requests_test.rb:155:in `test_invalid_compression'

OK:

Finished in 216.348452s, 7.9363 runs/s, 4619.0901 assertions/s.
1717 runs, 999333 assertions, 100 failures, 69 errors, 0 skips

bundle exec rails test:all  765.49s user 146.71s system 400% cpu 3:47.49 total

100 failures, 69 errors. That means of the 274 occurrances that I traded create to build_stubbed, it failed in 167 cases, worked in the other 105 cases it worked for.

Meh. Feels uncertain. If I could make minitest run tests in order, I could reliably fix the output, I think.

Even when scoping the build_stubbed to just model tests, I replaced 73 occurrences, getting 29 errors/failures. That's better than half, but not quite 2/3rds.

Filing this away as an option if I all of a sudden wanted to touch a lot of files in a sorta random way. I'd prob bring this to the maintainers to see if they cared, before adding it to the PR. Getting another minute off the test run time seems cool, might be worth it.

Would be cool if I could just re-use the same object somehow.

Thursday, April 18, 2024

Fresh run of the tests:

Finished in 196.287026s, 8.7474 runs/s, 5096.0576 assertions/s.
1717 runs, 1000290 assertions, 0 failures, 1 errors, 0 skips
bundle exec rails test:all  834.56s user 137.78s system 466% cpu 3:28.37 total

3.5 min total? we're cooking with gas.

Got the PR re-run against circle CI, huge wins on sped ups. I'm gonna try quickly doing a careful find-and-replace for build(:user) to build_stubbed(:user)

i'll empty the test log file, run it, save all the errors to a text file, and sort it, so I can have one full list of all fixes.

rm log/test.log
touch log/test.log
tail -f log/test.log

do find-and-replace, Replace 807 occurrences across 93 files with 'build_stubbed'?w

re-run tests, capture all errors. I expect 350 errors.

Finished in 140.512836s, 12.2195 runs/s, 7080.4635 assertions/s.
1717 runs, 994896 assertions, 253 failures, 227 errors, 0 skips
bundle exec rails test:all  504.92s user 98.86s system 407% cpu 2:28.12 total

progress. 477 errors. Half of them are good, half are not. hm.

Here's the full, clean list:

bin/rails test test/abilities/abilities_test.rb:47
bin/rails test test/abilities/api_abilities_test.rb:23
bin/rails test test/controllers/accounts_controller_test.rb:127
bin/rails test test/controllers/accounts_controller_test.rb:150
bin/rails test test/controllers/accounts_controller_test.rb:158
bin/rails test test/controllers/accounts_controller_test.rb:17
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:103
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:137
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:158
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:180
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:223
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:262
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:304
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:326
bin/rails test test/controllers/api/changeset_comments_controller_test.rb:36
bin/rails test test/controllers/api/changesets_controller_test.rb:101
bin/rails test test/controllers/api/changesets_controller_test.rb:114
bin/rails test test/controllers/api/changesets_controller_test.rb:1433
bin/rails test test/controllers/api/changesets_controller_test.rb:1470
bin/rails test test/controllers/api/changesets_controller_test.rb:1702
bin/rails test test/controllers/api/changesets_controller_test.rb:1748
bin/rails test test/controllers/api/changesets_controller_test.rb:1804
bin/rails test test/controllers/api/changesets_controller_test.rb:1862
bin/rails test test/controllers/api/changesets_controller_test.rb:1920
bin/rails test test/controllers/api/changesets_controller_test.rb:2001
bin/rails test test/controllers/api/changesets_controller_test.rb:2061
bin/rails test test/controllers/api/changesets_controller_test.rb:2161
bin/rails test test/controllers/api/changesets_controller_test.rb:2190
bin/rails test test/controllers/api/changesets_controller_test.rb:2237
bin/rails test test/controllers/api/changesets_controller_test.rb:2304
bin/rails test test/controllers/api/changesets_controller_test.rb:2360
bin/rails test test/controllers/api/changesets_controller_test.rb:2377
bin/rails test test/controllers/api/changesets_controller_test.rb:2459
bin/rails test test/controllers/api/changesets_controller_test.rb:2478
bin/rails test test/controllers/api/changesets_controller_test.rb:2507
bin/rails test test/controllers/api/changesets_controller_test.rb:2530
bin/rails test test/controllers/api/changesets_controller_test.rb:408
bin/rails test test/controllers/api/changesets_controller_test.rb:438
bin/rails test test/controllers/api/changesets_controller_test.rb:451
bin/rails test test/controllers/api/changesets_controller_test.rb:468
bin/rails test test/controllers/api/changesets_controller_test.rb:493
bin/rails test test/controllers/api/changesets_controller_test.rb:602
bin/rails test test/controllers/api/changesets_controller_test.rb:66
bin/rails test test/controllers/api/changesets_controller_test.rb:736
bin/rails test test/controllers/api/changesets_controller_test.rb:751
bin/rails test test/controllers/api/nodes_controller_test.rb:169
bin/rails test test/controllers/api/nodes_controller_test.rb:299
bin/rails test test/controllers/api/nodes_controller_test.rb:38
bin/rails test test/controllers/api/nodes_controller_test.rb:517
bin/rails test test/controllers/api/nodes_controller_test.rb:563
bin/rails test test/controllers/api/nodes_controller_test.rb:601
bin/rails test test/controllers/api/nodes_controller_test.rb:88
bin/rails test test/controllers/api/notes_controller_test.rb:224
bin/rails test test/controllers/api/notes_controller_test.rb:314
bin/rails test test/controllers/api/notes_controller_test.rb:361
bin/rails test test/controllers/api/notes_controller_test.rb:395
bin/rails test test/controllers/api/notes_controller_test.rb:415
bin/rails test test/controllers/api/notes_controller_test.rb:449
bin/rails test test/controllers/api/notes_controller_test.rb:566
bin/rails test test/controllers/api/notes_controller_test.rb:602
bin/rails test test/controllers/api/notes_controller_test.rb:856
bin/rails test test/controllers/api/notes_controller_test.rb:895
bin/rails test test/controllers/api/old_nodes_controller_test.rb:214
bin/rails test test/controllers/api/old_nodes_controller_test.rb:241
bin/rails test test/controllers/api/old_nodes_controller_test.rb:247
bin/rails test test/controllers/api/old_nodes_controller_test.rb:253
bin/rails test test/controllers/api/old_nodes_controller_test.rb:383
bin/rails test test/controllers/api/old_nodes_controller_test.rb:41
bin/rails test test/controllers/api/old_relations_controller_test.rb:225
bin/rails test test/controllers/api/old_relations_controller_test.rb:57
bin/rails test test/controllers/api/old_relations_controller_test.rb:80
bin/rails test test/controllers/api/old_relations_controller_test.rb:86
bin/rails test test/controllers/api/old_relations_controller_test.rb:92
bin/rails test test/controllers/api/old_ways_controller_test.rb:100
bin/rails test test/controllers/api/old_ways_controller_test.rb:121
bin/rails test test/controllers/api/old_ways_controller_test.rb:127
bin/rails test test/controllers/api/old_ways_controller_test.rb:133
bin/rails test test/controllers/api/old_ways_controller_test.rb:263
bin/rails test test/controllers/api/permissions_controller_test.rb:35
bin/rails test test/controllers/api/permissions_controller_test.rb:74
bin/rails test test/controllers/api/relations_controller_test.rb:216
bin/rails test test/controllers/api/relations_controller_test.rb:388
bin/rails test test/controllers/api/relations_controller_test.rb:420
bin/rails test test/controllers/api/relations_controller_test.rb:447
bin/rails test test/controllers/api/relations_controller_test.rb:465
bin/rails test test/controllers/api/relations_controller_test.rb:485
bin/rails test test/controllers/api/relations_controller_test.rb:507
bin/rails test test/controllers/api/relations_controller_test.rb:642
bin/rails test test/controllers/api/relations_controller_test.rb:673
bin/rails test test/controllers/api/relations_controller_test.rb:712
bin/rails test test/controllers/api/relations_controller_test.rb:737
bin/rails test test/controllers/api/relations_controller_test.rb:799
bin/rails test test/controllers/api/relations_controller_test.rb:839
bin/rails test test/controllers/api/relations_controller_test.rb:880
bin/rails test test/controllers/api/relations_controller_test.rb:911
bin/rails test test/controllers/api/relations_controller_test.rb:962
bin/rails test test/controllers/api/traces_controller_test.rb:142
bin/rails test test/controllers/api/traces_controller_test.rb:163
bin/rails test test/controllers/api/traces_controller_test.rb:182
bin/rails test test/controllers/api/traces_controller_test.rb:250
bin/rails test test/controllers/api/traces_controller_test.rb:309
bin/rails test test/controllers/api/traces_controller_test.rb:39
bin/rails test test/controllers/api/traces_controller_test.rb:59
bin/rails test test/controllers/api/traces_controller_test.rb:97
bin/rails test test/controllers/api/user_blocks_controller_test.rb:16
bin/rails test test/controllers/api/user_preferences_controller_test.rb:107
bin/rails test test/controllers/api/user_preferences_controller_test.rb:157
bin/rails test test/controllers/api/user_preferences_controller_test.rb:194
bin/rails test test/controllers/api/user_preferences_controller_test.rb:231
bin/rails test test/controllers/api/user_preferences_controller_test.rb:243
bin/rails test test/controllers/api/user_preferences_controller_test.rb:36
bin/rails test test/controllers/api/user_preferences_controller_test.rb:83
bin/rails test test/controllers/api/users_controller_test.rb:152
bin/rails test test/controllers/api/users_controller_test.rb:227
bin/rails test test/controllers/api/users_controller_test.rb:263
bin/rails test test/controllers/api/users_controller_test.rb:302
bin/rails test test/controllers/api/users_controller_test.rb:364
bin/rails test test/controllers/api/users_controller_test.rb:38
bin/rails test test/controllers/api/users_controller_test.rb:437
bin/rails test test/controllers/api/users_controller_test.rb:530
bin/rails test test/controllers/api/users_controller_test.rb:623
bin/rails test test/controllers/api/users_controller_test.rb:78
bin/rails test test/controllers/api/ways_controller_test.rb:140
bin/rails test test/controllers/api/ways_controller_test.rb:200
bin/rails test test/controllers/api/ways_controller_test.rb:282
bin/rails test test/controllers/api/ways_controller_test.rb:404
bin/rails test test/controllers/api/ways_controller_test.rb:536
bin/rails test test/controllers/api/ways_controller_test.rb:582
bin/rails test test/controllers/api/ways_controller_test.rb:630
bin/rails test test/controllers/api/ways_controller_test.rb:682
bin/rails test test/controllers/api/ways_controller_test.rb:758
bin/rails test test/controllers/api/ways_controller_test.rb:806
bin/rails test test/controllers/changesets_controller_test.rb:126
bin/rails test test/controllers/changesets_controller_test.rb:150
bin/rails test test/controllers/changesets_controller_test.rb:180
bin/rails test test/controllers/changesets_controller_test.rb:204
bin/rails test test/controllers/changesets_controller_test.rb:258
bin/rails test test/controllers/changesets_controller_test.rb:279
bin/rails test test/controllers/changesets_controller_test.rb:320
bin/rails test test/controllers/changesets_controller_test.rb:381
bin/rails test test/controllers/changesets_controller_test.rb:411
bin/rails test test/controllers/changesets_controller_test.rb:429
bin/rails test test/controllers/changesets_controller_test.rb:442
bin/rails test test/controllers/changesets_controller_test.rb:467
bin/rails test test/controllers/changesets_controller_test.rb:485
bin/rails test test/controllers/changesets_controller_test.rb:500
bin/rails test test/controllers/confirmations_controller_test.rb:275
bin/rails test test/controllers/confirmations_controller_test.rb:285
bin/rails test test/controllers/confirmations_controller_test.rb:304
bin/rails test test/controllers/confirmations_controller_test.rb:318
bin/rails test test/controllers/dashboards_controller_test.rb:20
bin/rails test test/controllers/diary_entries_controller_test.rb:126
bin/rails test test/controllers/diary_entries_controller_test.rb:150
bin/rails test test/controllers/diary_entries_controller_test.rb:162
bin/rails test test/controllers/diary_entries_controller_test.rb:177
bin/rails test test/controllers/diary_entries_controller_test.rb:201
bin/rails test test/controllers/diary_entries_controller_test.rb:227
bin/rails test test/controllers/diary_entries_controller_test.rb:253
bin/rails test test/controllers/diary_entries_controller_test.rb:351
bin/rails test test/controllers/diary_entries_controller_test.rb:360
bin/rails test test/controllers/diary_entries_controller_test.rb:425
bin/rails test test/controllers/diary_entries_controller_test.rb:467
bin/rails test test/controllers/diary_entries_controller_test.rb:477
bin/rails test test/controllers/diary_entries_controller_test.rb:495
bin/rails test test/controllers/diary_entries_controller_test.rb:515
bin/rails test test/controllers/diary_entries_controller_test.rb:636
bin/rails test test/controllers/diary_entries_controller_test.rb:681
bin/rails test test/controllers/diary_entries_controller_test.rb:725
bin/rails test test/controllers/diary_entries_controller_test.rb:745
bin/rails test test/controllers/diary_entries_controller_test.rb:776
bin/rails test test/controllers/diary_entries_controller_test.rb:807
bin/rails test test/controllers/diary_entries_controller_test.rb:839
bin/rails test test/controllers/diary_entries_controller_test.rb:871
bin/rails test test/controllers/diary_entries_controller_test.rb:902
bin/rails test test/controllers/diary_entries_controller_test.rb:920
bin/rails test test/controllers/diary_entries_controller_test.rb:932
bin/rails test test/controllers/diary_entries_controller_test.rb:957
bin/rails test test/controllers/diary_entries_controller_test.rb:975
bin/rails test test/controllers/diary_entries_controller_test.rb:989
bin/rails test test/controllers/friendships_controller_test.rb:113
bin/rails test test/controllers/friendships_controller_test.rb:121
bin/rails test test/controllers/friendships_controller_test.rb:164
bin/rails test test/controllers/friendships_controller_test.rb:191
bin/rails test test/controllers/friendships_controller_test.rb:25
bin/rails test test/controllers/friendships_controller_test.rb:79
bin/rails test test/controllers/issue_comments_controller_test.rb:4
bin/rails test test/controllers/issues_controller_test.rb:125
bin/rails test test/controllers/issues_controller_test.rb:151
bin/rails test test/controllers/issues_controller_test.rb:177
bin/rails test test/controllers/issues_controller_test.rb:205
bin/rails test test/controllers/issues_controller_test.rb:25
bin/rails test test/controllers/issues_controller_test.rb:4
bin/rails test test/controllers/issues_controller_test.rb:49
bin/rails test test/controllers/issues_controller_test.rb:73
bin/rails test test/controllers/issues_controller_test.rb:99
bin/rails test test/controllers/messages_controller_test.rb:107
bin/rails test test/controllers/messages_controller_test.rb:137
bin/rails test test/controllers/messages_controller_test.rb:167
bin/rails test test/controllers/messages_controller_test.rb:208
bin/rails test test/controllers/messages_controller_test.rb:232
bin/rails test test/controllers/messages_controller_test.rb:278
bin/rails test test/controllers/messages_controller_test.rb:326
bin/rails test test/controllers/messages_controller_test.rb:348
bin/rails test test/controllers/messages_controller_test.rb:371
bin/rails test test/controllers/messages_controller_test.rb:426
bin/rails test test/controllers/messages_controller_test.rb:56
bin/rails test test/controllers/messages_controller_test.rb:77
bin/rails test test/controllers/notes_controller_test.rb:129
bin/rails test test/controllers/notes_controller_test.rb:144
bin/rails test test/controllers/notes_controller_test.rb:28
bin/rails test test/controllers/notes_controller_test.rb:68
bin/rails test test/controllers/notes_controller_test.rb:84
bin/rails test test/controllers/oauth2_applications_controller_test.rb:115
bin/rails test test/controllers/oauth2_applications_controller_test.rb:140
bin/rails test test/controllers/oauth2_applications_controller_test.rb:159
bin/rails test test/controllers/oauth2_applications_controller_test.rb:186
bin/rails test test/controllers/oauth2_applications_controller_test.rb:216
bin/rails test test/controllers/oauth2_applications_controller_test.rb:41
bin/rails test test/controllers/oauth2_applications_controller_test.rb:56
bin/rails test test/controllers/oauth2_applications_controller_test.rb:77
bin/rails test test/controllers/oauth2_authorizations_controller_test.rb:105
bin/rails test test/controllers/oauth2_authorizations_controller_test.rb:123
bin/rails test test/controllers/oauth2_authorizations_controller_test.rb:145
bin/rails test test/controllers/oauth2_authorizations_controller_test.rb:163
bin/rails test test/controllers/oauth2_authorizations_controller_test.rb:25
bin/rails test test/controllers/oauth2_authorizations_controller_test.rb:47
bin/rails test test/controllers/oauth2_authorizations_controller_test.rb:69
bin/rails test test/controllers/oauth2_authorizations_controller_test.rb:83
bin/rails test test/controllers/oauth2_authorized_applications_controller_test.rb:17
bin/rails test test/controllers/oauth2_authorized_applications_controller_test.rb:38
bin/rails test test/controllers/oauth2_authorized_applications_controller_test.rb:63
bin/rails test test/controllers/oauth_clients_controller_test.rb:114
bin/rails test test/controllers/oauth_clients_controller_test.rb:133
bin/rails test test/controllers/oauth_clients_controller_test.rb:161
bin/rails test test/controllers/oauth_clients_controller_test.rb:185
bin/rails test test/controllers/oauth_clients_controller_test.rb:37
bin/rails test test/controllers/oauth_clients_controller_test.rb:53
bin/rails test test/controllers/oauth_clients_controller_test.rb:75
bin/rails test test/controllers/oauth_clients_controller_test.rb:89
bin/rails test test/controllers/passwords_controller_test.rb:124
bin/rails test test/controllers/passwords_controller_test.rb:25
bin/rails test test/controllers/preferences_controller_test.rb:23
bin/rails test test/controllers/profiles_controller_test.rb:18
bin/rails test test/controllers/redactions_controller_test.rb:112
bin/rails test test/controllers/redactions_controller_test.rb:133
bin/rails test test/controllers/redactions_controller_test.rb:159
bin/rails test test/controllers/redactions_controller_test.rb:61
bin/rails test test/controllers/redactions_controller_test.rb:83
bin/rails test test/controllers/reports_controller_test.rb:10
bin/rails test test/controllers/reports_controller_test.rb:30
bin/rails test test/controllers/reports_controller_test.rb:73
bin/rails test test/controllers/sessions_controller_test.rb:34
bin/rails test test/controllers/site_controller_test.rb:163
bin/rails test test/controllers/site_controller_test.rb:174
bin/rails test test/controllers/site_controller_test.rb:185
bin/rails test test/controllers/site_controller_test.rb:221
bin/rails test test/controllers/site_controller_test.rb:245
bin/rails test test/controllers/site_controller_test.rb:260
bin/rails test test/controllers/site_controller_test.rb:281
bin/rails test test/controllers/site_controller_test.rb:297
bin/rails test test/controllers/site_controller_test.rb:318
bin/rails test test/controllers/site_controller_test.rb:334
bin/rails test test/controllers/site_controller_test.rb:357
bin/rails test test/controllers/site_controller_test.rb:371
bin/rails test test/controllers/site_controller_test.rb:430
bin/rails test test/controllers/site_controller_test.rb:510
bin/rails test test/controllers/traces_controller_test.rb:112
bin/rails test test/controllers/traces_controller_test.rb:148
bin/rails test test/controllers/traces_controller_test.rb:173
bin/rails test test/controllers/traces_controller_test.rb:318
bin/rails test test/controllers/traces_controller_test.rb:344
bin/rails test test/controllers/traces_controller_test.rb:608
bin/rails test test/controllers/traces_controller_test.rb:641
bin/rails test test/controllers/traces_controller_test.rb:673
bin/rails test test/controllers/traces_controller_test.rb:689
bin/rails test test/controllers/traces_controller_test.rb:719
bin/rails test test/controllers/traces_controller_test.rb:756
bin/rails test test/controllers/user_blocks_controller_test.rb:104
bin/rails test test/controllers/user_blocks_controller_test.rb:139
bin/rails test test/controllers/user_blocks_controller_test.rb:176
bin/rails test test/controllers/user_blocks_controller_test.rb:212
bin/rails test test/controllers/user_blocks_controller_test.rb:271
bin/rails test test/controllers/user_blocks_controller_test.rb:286
bin/rails test test/controllers/user_blocks_controller_test.rb:346
bin/rails test test/controllers/user_blocks_controller_test.rb:394
bin/rails test test/controllers/user_blocks_controller_test.rb:423
bin/rails test test/controllers/user_blocks_controller_test.rb:470
bin/rails test test/controllers/user_blocks_controller_test.rb:510
bin/rails test test/controllers/user_blocks_controller_test.rb:529
bin/rails test test/controllers/user_blocks_controller_test.rb:69
bin/rails test test/controllers/user_mutes_controller_test.rb:19
bin/rails test test/controllers/user_mutes_controller_test.rb:28
bin/rails test test/controllers/user_mutes_controller_test.rb:45
bin/rails test test/controllers/user_roles_controller_test.rb:19
bin/rails test test/controllers/user_roles_controller_test.rb:79
bin/rails test test/controllers/users_controller_test.rb:137
bin/rails test test/controllers/users_controller_test.rb:154
bin/rails test test/controllers/users_controller_test.rb:183
bin/rails test test/controllers/users_controller_test.rb:212
bin/rails test test/controllers/users_controller_test.rb:241
bin/rails test test/controllers/users_controller_test.rb:340
bin/rails test test/controllers/users_controller_test.rb:349
bin/rails test test/controllers/users_controller_test.rb:369
bin/rails test test/controllers/users_controller_test.rb:391
bin/rails test test/controllers/users_controller_test.rb:405
bin/rails test test/controllers/users_controller_test.rb:417
bin/rails test test/controllers/users_controller_test.rb:511
bin/rails test test/controllers/users_controller_test.rb:537
bin/rails test test/controllers/users_controller_test.rb:556
bin/rails test test/controllers/users_controller_test.rb:587
bin/rails test test/controllers/users_controller_test.rb:664
bin/rails test test/controllers/users_controller_test.rb:708
bin/rails test test/controllers/users_controller_test.rb:96
bin/rails test test/helpers/changesets_helper_test.rb:15
bin/rails test test/helpers/changesets_helper_test.rb:4
bin/rails test test/helpers/note_helper_test.rb:15
bin/rails test test/helpers/user_helper_test.rb:56
bin/rails test test/helpers/user_helper_test.rb:78
bin/rails test test/integration/client_applications_test.rb:7
bin/rails test test/integration/compressed_requests_test.rb:103
bin/rails test test/integration/compressed_requests_test.rb:153
bin/rails test test/integration/compressed_requests_test.rb:4
bin/rails test test/integration/compressed_requests_test.rb:53
bin/rails test test/integration/oauth2_test.rb:20
bin/rails test test/integration/oauth2_test.rb:39
bin/rails test test/integration/oauth2_test.rb:5
bin/rails test test/integration/oauth2_test.rb:56
bin/rails test test/integration/oauth2_test.rb:73
bin/rails test test/integration/oauth_test.rb:17
bin/rails test test/integration/oauth_test.rb:27
bin/rails test test/integration/oauth_test.rb:38
bin/rails test test/integration/oauth_test.rb:6
bin/rails test test/integration/page_locale_test.rb:23
bin/rails test test/integration/page_locale_test.rb:4
bin/rails test test/integration/user_blocks_test.rb:24
bin/rails test test/integration/user_blocks_test.rb:4
bin/rails test test/integration/user_creation_test.rb:27
bin/rails test test/integration/user_creation_test.rb:48
bin/rails test test/integration/user_diaries_test.rb:6
bin/rails test test/integration/user_login_test.rb:100
bin/rails test test/integration/user_login_test.rb:1004
bin/rails test test/integration/user_login_test.rb:1084
bin/rails test test/integration/user_login_test.rb:109
bin/rails test test/integration/user_login_test.rb:1103
bin/rails test test/integration/user_login_test.rb:1121
bin/rails test test/integration/user_login_test.rb:1143
bin/rails test test/integration/user_login_test.rb:121
bin/rails test test/integration/user_login_test.rb:133
bin/rails test test/integration/user_login_test.rb:145
bin/rails test test/integration/user_login_test.rb:155
bin/rails test test/integration/user_login_test.rb:165
bin/rails test test/integration/user_login_test.rb:178
bin/rails test test/integration/user_login_test.rb:200
bin/rails test test/integration/user_login_test.rb:21
bin/rails test test/integration/user_login_test.rb:212
bin/rails test test/integration/user_login_test.rb:221
bin/rails test test/integration/user_login_test.rb:230
bin/rails test test/integration/user_login_test.rb:239
bin/rails test test/integration/user_login_test.rb:248
bin/rails test test/integration/user_login_test.rb:257
bin/rails test test/integration/user_login_test.rb:266
bin/rails test test/integration/user_login_test.rb:278
bin/rails test test/integration/user_login_test.rb:290
bin/rails test test/integration/user_login_test.rb:302
bin/rails test test/integration/user_login_test.rb:312
bin/rails test test/integration/user_login_test.rb:322
bin/rails test test/integration/user_login_test.rb:332
bin/rails test test/integration/user_login_test.rb:342
bin/rails test test/integration/user_login_test.rb:352
bin/rails test test/integration/user_login_test.rb:371
bin/rails test test/integration/user_login_test.rb:389
bin/rails test test/integration/user_login_test.rb:411
bin/rails test test/integration/user_login_test.rb:43
bin/rails test test/integration/user_login_test.rb:493
bin/rails test test/integration/user_login_test.rb:514
bin/rails test test/integration/user_login_test.rb:534
bin/rails test test/integration/user_login_test.rb:55
bin/rails test test/integration/user_login_test.rb:558
bin/rails test test/integration/user_login_test.rb:64
bin/rails test test/integration/user_login_test.rb:642
bin/rails test test/integration/user_login_test.rb:667
bin/rails test test/integration/user_login_test.rb:686
bin/rails test test/integration/user_login_test.rb:704
bin/rails test test/integration/user_login_test.rb:726
bin/rails test test/integration/user_login_test.rb:73
bin/rails test test/integration/user_login_test.rb:806
bin/rails test test/integration/user_login_test.rb:82
bin/rails test test/integration/user_login_test.rb:825
bin/rails test test/integration/user_login_test.rb:843
bin/rails test test/integration/user_login_test.rb:865
bin/rails test test/integration/user_login_test.rb:91
bin/rails test test/integration/user_login_test.rb:945
bin/rails test test/integration/user_login_test.rb:964
bin/rails test test/integration/user_login_test.rb:982
bin/rails test test/integration/user_terms_seen_test.rb:18
bin/rails test test/integration/user_terms_seen_test.rb:4
bin/rails test test/integration/user_terms_seen_test.rb:42
bin/rails test test/mailers/user_mailer_test.rb:48
bin/rails test test/mailers/user_mailer_test.rb:57
bin/rails test test/mailers/user_mailer_test.rb:72
bin/rails test test/models/changeset_test.rb:75
bin/rails test test/models/issue_test.rb:12
bin/rails test test/models/note_test.rb:50
bin/rails test test/models/oauth_token_test.rb:15
bin/rails test test/models/relation_test.rb:184
bin/rails test test/models/relation_test.rb:210
bin/rails test test/models/relation_test.rb:236
bin/rails test test/models/trace_test.rb:11
bin/rails test test/models/user_mute_test.rb:13
bin/rails test test/models/user_mute_test.rb:4
bin/rails test test/models/user_preference_test.rb:15
bin/rails test test/models/user_preference_test.rb:5
bin/rails test test/models/user_test.rb:139
bin/rails test test/models/user_test.rb:153
bin/rails test test/models/user_test.rb:174
bin/rails test test/models/user_test.rb:186
bin/rails test test/models/user_test.rb:197
bin/rails test test/models/user_test.rb:215
bin/rails test test/models/user_test.rb:22
bin/rails test test/models/user_test.rb:235
bin/rails test test/models/user_test.rb:29
bin/rails test test/models/user_test.rb:294
bin/rails test test/models/user_test.rb:307
bin/rails test test/models/user_test.rb:319
bin/rails test test/models/user_test.rb:338
bin/rails test test/models/user_test.rb:347
bin/rails test test/models/user_test.rb:356
bin/rails test test/models/user_test.rb:366
bin/rails test test/models/user_test.rb:377
bin/rails test test/system/account_deletion_test.rb:23
bin/rails test test/system/account_deletion_test.rb:34
bin/rails test test/system/account_deletion_test.rb:45
bin/rails test test/system/account_deletion_test.rb:57
bin/rails test test/system/account_deletion_test.rb:71
bin/rails test test/system/account_deletion_test.rb:85
bin/rails test test/system/account_deletion_test.rb:9
bin/rails test test/system/changeset_comments_test.rb:126
bin/rails test test/system/changeset_comments_test.rb:143
bin/rails test test/system/changeset_comments_test.rb:26
bin/rails test test/system/changeset_comments_test.rb:4
bin/rails test test/system/diary_entry_test.rb:12
bin/rails test test/system/diary_entry_test.rb:40
bin/rails test test/system/diary_entry_test.rb:68
bin/rails test test/system/history_test.rb:19
bin/rails test test/system/history_test.rb:6
bin/rails test test/system/issues_test.rb:11
bin/rails test test/system/issues_test.rb:149
bin/rails test test/system/issues_test.rb:73
bin/rails test test/system/messages_test.rb:16
bin/rails test test/system/messages_test.rb:28
bin/rails test test/system/messages_test.rb:4
bin/rails test test/system/note_comments_test.rb:107
bin/rails test test/system/note_comments_test.rb:25
bin/rails test test/system/note_comments_test.rb:49
bin/rails test test/system/note_comments_test.rb:83
bin/rails test test/system/oauth2_test.rb:4
bin/rails test test/system/preferences_test.rb:13
bin/rails test test/system/preferences_test.rb:4
bin/rails test test/system/report_diary_comment_test.rb:17
bin/rails test test/system/report_diary_entry_test.rb:16
bin/rails test test/system/report_diary_entry_test.rb:37
bin/rails test test/system/report_diary_entry_test.rb:60
bin/rails test test/system/report_note_test.rb:12
bin/rails test test/system/report_note_test.rb:33
bin/rails test test/system/report_user_test.rb:12
bin/rails test test/system/report_user_test.rb:33
bin/rails test test/system/user_blocks_test.rb:30
bin/rails test test/system/user_blocks_test.rb:40
bin/rails test test/system/user_blocks_test.rb:55
bin/rails test test/system/user_email_change_test.rb:10
bin/rails test test/system/user_logout_test.rb:14
bin/rails test test/system/user_logout_test.rb:26
bin/rails test test/system/user_logout_test.rb:37
bin/rails test test/system/user_logout_test.rb:4
bin/rails test test/system/user_muting_test.rb:27
bin/rails test test/system/user_muting_test.rb:7
bin/rails test test/system/user_status_change_test.rb:21
bin/rails test test/system/user_status_change_test.rb:9
bin/rails test test/system/user_suspension_test.rb:4
bin/rails test test/system/view_communities_test.rb:11

bleh. lets see how this goes.

Manually fixed test/controllers/api/changesets_controller_test.rb, cannot handle any changes there, can exclude touching this file in the future.

exclude:

  • test/models/user_test.rb
  • test/controllers/api/changeset_comments_controller_test.rb

Re-doing, reset some files to the original form, now we've got:

Finished in 152.505154s, 11.2586 runs/s, 6528.3958 assertions/s.
1717 runs, 995614 assertions, 170 failures, 187 errors, 0 skips

bundle exec rails test:all  598.56s user 105.53s system 435% cpu 2:41.67 total

370 errors. This is mega annoying, abandoning this path. It's so fragile, I can kinda infer what sort of tests might be fine with a stubbed user rather than one in the DB, but it's time consuming to find them all. Going to avoid this path.

Lets get test-prof working, now. I'm curious to see a single report, and while I'm getting it closer to working, I've still not gotten it to fully work.

OK, getting some working.

 b (my alias for `bundle exec`) rails test  test/models/diary_comment_test.rb --verbose --event-prof='sql.active_record'

but erroring when I run on the whole test suite, or more than a single file.

b rails test  test/controllers/api/changeset_comments_controller_test.rb --verbose --event-prof='sql.active_record'

the verbose flag is a nice add, btw. Helps get a sense of timing things, along with tailing logs and puts statements.

[...]

Got a response from a maintainer, led to a lovely refactor of the factory update. In a different repo (mastadon, I just started looking at their project) I saw:

keypair     = OpenSSL::PKey::RSA.new(2048)
public_key  = keypair.public_key.to_pem
private_key = keypair.to_pem


Fabricator(:account) do
  transient :suspended, :silenced
  username            { sequence(:username) { |i| "#{Faker::Internet.user_name(separators: %w(_))}#{i}" } }
  last_webfingered_at { Time.now.utc }
  public_key          { public_key }

Updated the PR with something similar. Re-running tests locally. Working except a new bug related to thread safety:

objc[99230]: +[__NSCFConstantString initialize] may have been in progress in another thread when fork() was called. We cannot safely call it or ignore it in the fork() child process. Crashing instead. Set a breakpoint on objc_initializeAfterForkError to debug.

trying export DISABLE_SPRING=true, adding to zshrc. still seeing error. i expect terminal to hang now, and it's messing with my timing output. I think the PR is fine, though, and I have appetite for no more than about 2 more minutes on this.

no dice. don't care. I just got mastodon running on my environment, added some python and other things, probably should just restart my laptop for the hell of it, i'll do that later.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment