Welcome to the RSpec show! But before we unveil the unedited database logging from your test suite, let’s first enable logging to reveal what’s truly going on behind the scenes. We’ll be taking a look at what logs come out of RSpec and what the logging means to you. We will also take a look at some tools to use to help identify and reduce our database calls, which in turn will help speed up our tests.
# Configure logging level (e.g., :debug, :info, :warn, :error, :fatal)
config.log_level = :debug
# Specify the log file path
config.logger = Logger.new(Rails.root.join('log', 'test.log'))After enabling logging, we proceed to run our tests and closely examine each step of the process. We’ll observe the outcomes under various conditions: first, when no tests are present; next, when no objects are being built intentionally; and finally, when objects are indeed constructed. In our test file, we’ve set up the model but haven’t written any test code yet. So lets take a look at when we create a spec file with no tests.
RSpec.describe Post, type: :model do
endD, [2024-03-28T09:29:50.408860 #40563] DEBUG -- : ActiveRecord::InternalMetadata Pluck (0.6ms) SELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 LIMIT $2 [["key", "schema_sha1"], ["LIMIT", 1]]
D, [2024-03-28T09:29:50.431043 #40563] DEBUG -- : ActiveRecord::SchemaMigration Pluck (0.9ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASCWhen we’re in DEBUG mode (D), the logs provide us with essential information about what’s happening behind the scenes when we run our test suite:
- Timestamp: [2024-03-28T09:29:50.408860 #40563] – This timestamp helps us track when each action occurs in the test suite.
- ActiveRecord::InternalMetadata Pluck: This log entry pertains to the
schema_sha1inar_internal_metadata. ActiveRecord usesschema_sha1to monitor changes in the database schema. It compares the recorded hash with the current schema to ensure they match. If not, ActiveRecord may raise errors or prompt database migration to update the schema. - ActiveRecord::SchemaMigration Pluck: Similar to the previous entry, this log deals with migration versions stored in the schema_migrations table. ActiveRecord compares these versions with migration files in the
db/migratedirectory. This comparison helps manage the execution order of migrations and prevents duplications.
These logs provide insights into why we might encounter ActiveRecord errors prompting us to run migrations if there are any pending changes. However, at this stage, we haven’t executed any tests. Let’s proceed by adding our first test.
RSpec.describe Post, type: :model do
describe 'associations' do
it { should belong_to(:user) }
end
endWe’ll ignore the schema because that happens every time we run our command line prompt, but now we have these two TRANSACTION blocks.
D, [2024-03-28T10:14:25.875360 #41169] DEBUG -- : TRANSACTION (0.1ms) BEGIN
D, [2024-03-28T10:14:25.930719 #41169] DEBUG -- : TRANSACTION (0.2ms) ROLLBACKIf you add another test that involves creating objects, the database setup and teardown process will still occur as usual. Here’s how it would work:
- Database Setup (BEGIN): When the test suite runs, it will set up the database environment by beginning a transaction (BEGIN). This allows the test to create any necessary objects, such as records in the database, to fulfill the requirements of the test.
- Executing the Test: The new test, which involves creating objects, will run and perform its assertions or validations against the objects created within the test.
- Database Teardown (ROLLBACK): After the test completes, the database will roll back the transaction (ROLLBACK) to its original state. This rollback operation effectively destroys any objects created during the test, ensuring a clean and isolated environment for each test.
So, adding another test that creates objects will follow the same database setup and teardown process, maintaining the integrity and isolation of each test case.
RSpec.describe Post, type: :model do
describe 'associations' do
it { should belong_to(:user) }
it { should have_many(:tags) }
end
endWe run the tests, a total of 2 examples
D, [2024-03-28T10:22:37.765599 #41374] DEBUG -- : TRANSACTION (0.1ms) BEGIN
D, [2024-03-28T10:22:37.819168 #41374] DEBUG -- : TRANSACTION (0.2ms) ROLLBACK
D, [2024-03-28T10:22:37.820053 #41374] DEBUG -- : TRANSACTION (0.1ms) BEGIN
D, [2024-03-28T10:22:37.823172 #41374] DEBUG -- : TRANSACTION (0.2ms) ROLLBACKUnderstanding the intricacies of test aggregation in RSpec reveals the critical role it plays in optimizing test execution time. Consider this: with each new test block, we incur the overhead of starting a transaction (BEGIN) and rolling it back (ROLLBACK) afterward, even if no objects are created. This seemingly minor operation, repeated across multiple tests, can add up to a significant time sink.
By aggregating tests within the same block where possible, we eliminate redundant transaction operations, saving valuable milliseconds in the process. While this may seem negligible at a small scale, it becomes increasingly impactful as test suites grow in size and complexity.
This insight into how RSpec and the database interact between tests not only sheds light on potential time sinks but also underscores the importance of strategic testing practices for efficient software development.
RSpec.describe Post, type: :model do
describe 'associations' do
it do
should belong_to(:user)
should have_many(:tags)
end
end
context "class methods" do
describe ".total_count" do
before { create(:post) }
it "returns the total count of posts" do
expect(Post.total_count).to eq(1)
end
end
end
endIn our test, we’ll create a new Post object and use the total_count class method to verify that it returns the correct count of all Post objects. When we use create(:post), it invokes the factory for Post, but what exactly is included when this factory is called?
Understanding what attributes and associations are included when using the create(:post) method is crucial for ensuring accurate testing and a clear understanding of our data setup. Let’s dive deeper into the specifics of what happens behind the scenes when we create a Post object using FactoryBot.
FactoryBot.define do
factory :post do
title { 'Sample Post' }
content { 'This is a sample post content.' }
association :author, factory: :user
user
category
end
endUpon examining the factory, we observe that before creating a Post, three additional objects are also created: an author (using the user factory), a user linked to the user_id column, and a category. Each of these objects incurs the overhead of building and saving, adding to the overall time required for test execution.
As a result, after running the test, our logs would reflect these operations and potentially show the creation and saving of these additional objects, providing insights into the sequence of actions taken during the test.
D, [2024-03-28T10:35:29.578767 #41901] DEBUG -- : TRANSACTION (0.1ms) BEGIN
D, [2024-03-28T10:35:29.590554 #41901] DEBUG -- : TRANSACTION (0.2ms) SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.592240 #41901] DEBUG -- : User Create (1.1ms) INSERT INTO "users" ("name", "email", "password_digest", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["name", "John Doe"], ["email", "john@example.com"], ["password_digest", "$2a$04$9ZSRZnjPSOCbiPzoBpUK.ONXNYjAd444exOWYLRYMfBYyH8ipaaYq"], ["created_at", "2024-03-28 17:35:29.589738"], ["updated_at", "2024-03-28 17:35:29.589738"]]
D, [2024-03-28T10:35:29.592988 #41901] DEBUG -- : TRANSACTION (0.2ms) RELEASE SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.595450 #41901] DEBUG -- : TRANSACTION (0.2ms) SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.596187 #41901] DEBUG -- : User Create (0.3ms) INSERT INTO "users" ("name", "email", "password_digest", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["name", "John Doe"], ["email", "john@example.com"], ["password_digest", "$2a$04$xCohIqB9Ht5udSQTSjDbYun2VboIcPXivm/0rpQytIDi4rZKzEVy6"], ["created_at", "2024-03-28 17:35:29.595004"], ["updated_at", "2024-03-28 17:35:29.595004"]]
D, [2024-03-28T10:35:29.596751 #41901] DEBUG -- : TRANSACTION (0.1ms) RELEASE SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.603114 #41901] DEBUG -- : TRANSACTION (0.2ms) SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.604178 #41901] DEBUG -- : Category Create (0.6ms) INSERT INTO "categories" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id" [["name", "test"], ["created_at", "2024-03-28 17:35:29.602595"], ["updated_at", "2024-03-28 17:35:29.602595"]]
D, [2024-03-28T10:35:29.604545 #41901] DEBUG -- : TRANSACTION (0.1ms) RELEASE SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.605624 #41901] DEBUG -- : TRANSACTION (0.1ms) SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.607021 #41901] DEBUG -- : Post Create (1.1ms) INSERT INTO "posts" ("title", "content", "user_id", "category_id", "created_at", "updated_at", "published_at", "published", "author_id") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id" [["title", "Sample Post"], ["content", "This is a sample post content."], ["user_id", 418], ["category_id", 205], ["created_at", "2024-03-28 17:35:29.605099"], ["updated_at", "2024-03-28 17:35:29.605099"], ["published_at", nil], ["published", false], ["author_id", 417]]
D, [2024-03-28T10:35:29.607488 #41901] DEBUG -- : TRANSACTION (0.2ms) RELEASE SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.608564 #41901] DEBUG -- : Post Count (0.5ms) SELECT COUNT(*) FROM "posts"
D, [2024-03-28T10:35:29.609437 #41901] DEBUG -- : TRANSACTION (0.1ms) ROLLBACKD, [2024-03-28T10:35:29.592240 #41901] DEBUG -- : User Create (1.1ms) INSERT INTO "users" ("name", "email", "password_digest", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["name", "John Doe"], ["email", "john@example.com"], ["password_digest", "$2a$04$9ZSRZnjPSOCbiPzoBpUK.ONXNYjAd444exOWYLRYMfBYyH8ipaaYq"], ["created_at", "2024-03-28 17:35:29.589738"], ["updated_at", "2024-03-28 17:35:29.589738"]]
D, [2024-03-28T10:35:29.592988 #41901] DEBUG -- : TRANSACTION (0.2ms) RELEASE SAVEPOINT active_record_1
D, [2024-03-28T10:35:29.595450 #41901] DEBUG -- : TRANSACTION (0.2ms) SAVEPOINT active_record_1As we progress through the test, the sequence unfolds with the creation of various objects. Initially, we create the user for the author of the post, resulting in a User Create (1.1ms) database call generated from the user factory. Following this, we encounter a RELEASE SAVEPOINT followed by a new SAVEPOINT within the Transaction. This structure is designed to ensure that each object’s operations are encapsulated within its own SAVEPOINT within the database transaction.
This meticulous approach offers granular control over transaction rollback behavior, particularly valuable when isolating changes made to individual objects. The subsequent blocks in our log mirror this pattern: creating a user for the user_id association on the Post and then creating a Category object. Finally, we create the Post itself, utilizing the previously established objects in the process.
D, [2024-03-28T10:35:29.607021 #41901] DEBUG -- : Post Create (1.1ms) INSERT INTO "posts" ("title", "content", "user_id", "category_id", "created_at", "updated_at", "published_at", "published", "author_id") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id" [["title", "Sample Post"], ["content", "This is a sample post content."], ["user_id", 418], ["category_id", 205], ["created_at", "2024-03-28 17:35:29.605099"], ["updated_at", "2024-03-28 17:35:29.605099"], ["published_at", nil], ["published", false], ["author_id", 417]]Then we finally get to the test and then we rollback the entire database.
D, [2024-03-28T10:35:29.608564 #41901] DEBUG -- : Post Count (0.5ms) SELECT COUNT(*) FROM "posts"
D, [2024-03-28T10:35:29.609437 #41901] DEBUG -- : TRANSACTION (0.1ms) ROLLBACKTracking object creation is made convenient with tools like TestProf from Evil Martians, a favorite RSpec gem of mine. Enabling the factory usage check with FPROF=1 bundle exec rspec spec/models/post_spec.rb provides us with terminal output detailing the number of objects created during our two tests. In reviewing this output, we can observe that two users (as seen in the logs), along with one post and one category, were created. The total time taken for object creation offers valuable insights, especially as our test suites scale, helping us identify potential bottlenecks in testing times.
Additionally, TestProf highlights an important aspect: the ‘top-level’ focus indicates that we primarily care about the Post object. We’re not directly utilizing or interacting with the other objects created. To optimize this test file’s speed, it’s beneficial to minimize object creation to only what’s necessary and actively used within the tests.
[TEST PROF INFO] Factories usage
Total: 4
Total top-level: 1
Total time: 00:00.030 (out of 00:00.642)
Total uniq factories: 3
total top-level total time time per call top-level time name
2 0 0.0165s 0.0083s 0.0000s user
1 1 0.0302s 0.0302s 0.0302s post
1 0 0.0093s 0.0093s 0.0000s categoryTo reduce object building overhead, we can optimize the creation process. While we need the IDs for the post creation, stubbing out these objects entirely isn’t feasible. However, we can minimize the number of savepoints and combine post creation into a single transaction. This involves modifying our factory for Post and introducing a new ‘stubbed’ factory.
By streamlining the creation process and bundling related operations within a single transaction, we can significantly reduce the time spent on object creation, thereby improving the overall efficiency of our test suite.
factory :stubbed_post do
title { 'Stubbed Post' }
content { 'This is a stubbed post content.' }
author { build(:user)}
user { build(:user) }
category { build(:category) }
endInstead of using create(:post), we can utilize create(:stubbed_post) in our tests. While the resulting log may appear similar, with INSERT operations for users and categories alongside the post, the key difference lies in the absence of new SAVEPOINT markers. This simple adjustment reduces the timing overhead by approximately 0.9ms per transaction.
While this might seem trivial at first glance, the impact becomes significant as our test suite scales. With multiple tests creating objects repeatedly, even small reductions in transaction time accumulate. This underscores the importance of optimizing object creation processes to maintain efficient testing practices.
[TEST PROF INFO] Factories usage
Total: 1
Total top-level: 1
Total time: 00:00.027 (out of 00:00.639)
Total uniq factories: 1
total top-level total time time per call top-level time name
1 1 0.0278s 0.0278s 0.0278s stubbed_postD, [2024-03-28T11:21:10.347867 #43697] DEBUG -- : TRANSACTION (0.2ms) SAVEPOINT active_record_1
D, [2024-03-28T11:21:10.349157 #43697] DEBUG -- : Category Create (0.7ms) INSERT INTO "categories" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id" [["name", "test"], ["created_at", "2024-03-28 18:21:10.347069"], ["updated_at", "2024-03-28 18:21:10.347069"]]
D, [2024-03-28T11:21:10.350704 #43697] DEBUG -- : User Create (0.4ms) INSERT INTO "users" ("name", "email", "password_digest", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["name", "John Doe"], ["email", "john@example.com"], ["password_digest", "$2a$04$aojSFU2/Grnpra9d6POI1eDRwftp8iTr.V1HaY71.rycB4XIwu43G"], ["created_at", "2024-03-28 18:21:10.349777"], ["updated_at", "2024-03-28 18:21:10.349777"]]
D, [2024-03-28T11:21:10.351531 #43697] DEBUG -- : User Create (0.2ms) INSERT INTO "users" ("name", "email", "password_digest", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["name", "John Doe"], ["email", "john@example.com"], ["password_digest", "$2a$04$eGo2RE5J7fDPqoMnVszAbuqd1H/wklNjIe1xbJ8YWYStRcn80loRK"], ["created_at", "2024-03-28 18:21:10.351010"], ["updated_at", "2024-03-28 18:21:10.351010"]]
D, [2024-03-28T11:21:10.353507 #43697] DEBUG -- : Post Create (1.2ms) INSERT INTO "posts" ("title", "content", "user_id", "category_id", "created_at", "updated_at", "published_at", "published", "author_id") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id" [["title", "Stubbed Post"], ["content", "This is a stubbed post content."], ["user_id", 443], ["category_id", 218], ["created_at", "2024-03-28 18:21:10.351694"], ["updated_at", "2024-03-28 18:21:10.351694"], ["published_at", nil], ["published", false], ["author_id", 444]]
D, [2024-03-28T11:21:10.354098 #43697] DEBUG -- : TRANSACTION (0.2ms) RELEASE SAVEPOINT active_record_1
D, [2024-03-28T11:21:10.355534 #43697] DEBUG -- : Post Count (0.6ms) SELECT COUNT(*) FROM "posts"
D, [2024-03-28T11:21:10.356767 #43697] DEBUG -- : TRANSACTION (0.2ms) ROLLBACK[TEST PROF INFO] Factories usage
Total: 400
Total top-level: 100
Total time: 00:01.353 (out of 00:02.242)
Total uniq factories: 3
total top-level total time time per call top-level time name
200 0 0.7888s 0.0039s 0.0000s user
100 100 1.3530s 0.0135s 1.3530s post
100 0 0.2142s 0.0021s 0.0000s category
--------------------------------------------------------------------------
[TEST PROF INFO] Factories usage
Total: 100
Total top-level: 100
Total time: 00:01.072 (out of 00:01.947)
Total uniq factories: 1
total top-level total time time per call top-level time name
100 100 1.0721s 0.0107s 1.0721s stubbed_postThis comparison highlights that by combining object creation into a single transaction, the test runtime can be significantly reduced, showcasing the importance of optimizing object creation processes for efficient test execution.
Imagine if we could streamline our tests by reusing the same object instead of creating multiple identical ones. Fortunately, with TestProf, we have access to a powerful feature called before_all. This block, akin to before(:all) but with added speed optimizations, allows us to initialize our objects once at the beginning of the test suite.
By leveraging before_all at the top of our spec file, we can reduce object creation calls to just one, resulting in a significant 4x speed improvement. This approach not only speeds up our tests but also promotes cleaner and more efficient testing practices.
Finished in 0.35843 seconds (files took 2.64 seconds to load)
100 examples, 0 failures
[TEST PROF INFO] Factories usage
Total: 1
Total top-level: 1
Total time: 00:00.048 (out of 00:00.966)
Total uniq factories: 1
total top-level total time time per call top-level time name
1 1 0.0483s 0.0483s 0.0483s stubbed_post
----------------------------------------------------------------------
...
D, [2024-03-28T11:39:21.668740 #45202] DEBUG -- : TRANSACTION (0.1ms) SAVEPOINT active_record_1
D, [2024-03-28T11:39:21.669652 #45202] DEBUG -- : Post Count (0.3ms) SELECT COUNT(*) FROM "posts"
D, [2024-03-28T11:39:21.670055 #45202] DEBUG -- : TRANSACTION (0.1ms) ROLLBACK TO SAVEPOINT active_record_1
...Our test logs now show a significant reduction in size, reflecting a streamlined process where we create the base object once and then efficiently handle subsequent transactions with minimal overhead. By leveraging techniques like TRANSACTION and ROLLBACK TO SAVEPOINT, we eliminate the need to repeatedly build objects, leading to a remarkable test time improvement down to just 0.34 seconds—almost a whole second faster than the ‘optimized’ build speed.
Applying these practices to real-world applications reveals common pitfalls, such as needlessly creating duplicate objects within context or describe blocks. This practice not only bloats object counts but also slows down test execution unnecessarily. While adding or modifying objects is valid when needed, it’s crucial to rethink excessive object creation and reuse existing ones wherever possible.
Tools like TestProf shed light on the time-consuming nature of building and rolling back objects in tests, prompting us to simplify test files, organize them effectively, and create factories for the minimum required objects. Understanding the impact of our testing practices on the test database is as crucial as optimizing queries and transactions for the production database. After all, the test database deserves attention too!
Leave a Reply