Experiment: Support for creating unlogged tables to speed up tests

[mgibowski]

I'm curious to hear from folks about the impact and whether it's worth adding such a feature at all.

If you want to try it on your codebase, follow these steps:

1. Update your dependencies to:

{:ecto_sql, git: "https://github.com/mgibowski/ecto_sql.git", branch: "unlogged", override: true},
{:ecto, git: "https://github.com/elixir-ecto/ecto.git", override: true},

2. In the test.exs file, add the following configuration:

config :your_app, YourApp.Repo,
  create_unlogged_tables: true

3. And reset your database in the test environment:

MIX_ENV=test mix ecto.reset

[josevalim]

It would be nice if people could post time mix test before and after the steps above. @mgibowski feel free to post yours, I will tweet this PR and get some attention. Feel free to share on places like ElixirForum too.

[josevalim]

Note for the future: we should probably call this "table.modifier" or something, because there are other options, such as temporary tables in MySQL, global/local, etc. It should be a plain string.

[PJUllrich]

# Before adding the config to test.exs
mix test  10.26s user 3.88s system 352% cpu 4.007 total
mix test  9.94s user 3.61s system 381% cpu 3.551 total
mix test  10.07s user 3.66s system 382% cpu 3.592 total

# After adding the config to text.exs
mix test  9.99s user 3.82s system 391% cpu 3.524 total
mix test  10.05s user 3.67s system 386% cpu 3.549 total
mix test  9.93s user 3.66s system 384% cpu 3.533 total
mix test  10.01s user 3.65s system 388% cpu 3.519 total

# After reverting back to original
mix test  9.97s user 3.64s system 382% cpu 3.560 total
mix test  9.99s user 3.62s system 374% cpu 3.635 total
mix test  10.14s user 3.74s system 398% cpu 3.485 total

All test runs logged this. Some had 2.5s instead of 2.4s.

Finished in 2.4 seconds (2.4s async, 0.00s sync)
582 tests, 0 failures, 1 excluded

My project is maybe too small to properly measure these effects. It has 11 tables, 2 of which are oban_jobs and oban_peers.

[mgibowski]

It would be nice if people could post time mix test before and after the steps above. @mgibowski feel free to post yours, I will tweet this PR and get some attention. Feel free to share on places like ElixirForum too.

I tried using unlogged tables some time ago on a project I no longer have access to. It had around 400 tests, and the improvement seemed to be about 10% / 1.5 seconds.
I tried this branch yesterday on changelog.org and the hexpm codebases, and I cannot tell there is any improvement. Test execution times are sometimes faster and sometimes slower.

[warmwaffles]

This wont work for those of us who use mix ecto.dump and mix ecto.load. I really wish it could. I was able to run it locally from zero (ran migrations from scratch) but some of our tests fail (some tables were created outside of our application's lifecycle) so it's not apples to apples for run time.

Before

Finished in 80.4 seconds (64.5s async, 15.9s sync)
32 doctests, 53 properties, 9189 tests, 0 failures, 3 skipped

Randomized with seed 804265
[os_mon] memory supervisor port (memsup): Erlang has closed
[os_mon] cpu supervisor port (cpu_sup): Erlang has closed

________________________________________________________
Executed in   82.29 secs    fish           external
   usr time  478.11 secs  493.00 micros  478.11 secs
   sys time  115.22 secs   78.00 micros  115.22 secs

After

Finished in 83.7 seconds (66.8s async, 16.8s sync)
32 doctests, 53 properties, 9189 tests, 32 failures, 3 skipped

Randomized with seed 129402
[os_mon] memory supervisor port (memsup): Erlang has closed
[os_mon] cpu supervisor port (cpu_sup): Erlang has closed

________________________________________________________
Executed in   85.57 secs    fish           external
   usr time  500.81 secs   65.29 millis  500.74 secs
   sys time  121.15 secs   16.20 millis  121.14 secs

[s3cur3]

Here are the results on Felt's codebase, running on my M1 MacBook Air. I've included our tests tagged :slow, which we normally only run in CI, since those are the most database intensive:

Condition	Total runtime (reported by mix)	Seconds async	Seconds sync	Real	User	Sys
Before	134.1	58.8	75.3	2m16.029s	2m16.029s	0m40.376s
Before	125.9	50.6	75.2	2m7.883s	3m9.408s	0m37.810s
Before	144.6	54.6	89.9	2m26.629s	3m11.503s	0m38.874s
After	128.4	51.4	77.0	2m10.544s	3m9.499s	0m36.942s
After	125.3	51.3	73.9	2m7.377s	3m10.357s	0m39.277s
After	124.6	49.6	74.9	2m6.678s	3m11.164s	0m37.738s

Mean total runtime: 134.9 before, 125.9 seconds after, for a speedup in the range of 7%.

If there's interest, I'd be happy to run these overnight to get something closer to a statistically significant sample. (The variance on the "before" number in particular is a little weird to me.) I could also run it on an Intel Mac.

UPDATE: Here are the results of running time over 10 consecutive iterations, both with and without our :slow (DB-intensive) tests:

Condition	Real	User	Sys
Before, excluding :slow	10m24.750s	24m55.157s	5m41.607s
Before, including :slow	24m32.712s	36m15.315s	7m8.092s
After, excluding :slow	10m19.023s	25m20.022s	5m41.499s
After, including :slow	23m24.205s	36m9.770s	6m55.615s

Thus, there was very little difference on our "fast" tests, and a savings of about 5% on the full suite.

[dbernheisel]

for me, tldr, ~8% faster async runs, ~3% slower sync runs, but overall 2% improvement if you are looking at the clock (real time).

Setup: MIX_ENV=test mix do deps.get, compile, ecto.drop, ecto.create, ecto.load, ecto.migrate
Test: repeat 5 { time mix test }
(in retrospect, specifying the test seed would net a more consistent representation)

In order to do this, since I'm using ecto.load and squashed migrations in the structure.sql, I had to replace all its CREATE TABLE statements with CREATE UNLOGGED TABLE, otherwise I ran into a postgres error constraints on permanent tables may reference only permanent tables (unlogged tables are not considered "permanent" tables). This would diverge from the actual structure in deployed environments, but perhaps that would be ok; may make some folks uncomfortable.

markdown

BEFORE	async	sync	real	user	cpu
run 1	68.2	41.7	152.18	24.71	112.82
run 2	58.3	36.5	154.04	26.62	97.82
run 3	44.6	36.8	152.31	25.1	84.21
run 4	64.8	38.6	150.39	24.66	106.27
run 5	51.9	39.3	149.84	25.52	94.14
AVG	57.56	38.58	151.752	25.322	99.052
MEDIAN	58.3	38.6	152.18	25.1	97.82
MAX	68.2	41.7	154.04	26.62	112.82
MIN	44.6	36.5	149.84	24.66	84.21

AFTER	async	sync	real	user	cpu
run 1	50.6	42.1	148.52	24.77	95.65
run 2	45.6	39.1	149.54	25.2	87.73
run 3	56.7	39.2	150.31	26.74	98.89
run 4	61.2	38.9	150.73	24.57	103.08
run 5	50.7	39.9	142.67	25.81	93.49
AVG	52.96	39.84	148.354	25.418	95.768
MEDIAN	50.7	39.2	149.54	25.2	95.65
MAX	61.2	42.1	150.73	26.74	103.08
MIN	45.6	38.9	142.67	24.57	87.73

[HarshBalyan]

As mentioned in some previous comments, getting

** (Postgrex.Error) ERROR 42P16 (invalid_table_definition) constraints on permanent tables may reference only permanent tables
    (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:1057: Ecto.Adapters.SQL.raise_sql_call_error/1
    (elixir 1.15.7) lib/enum.ex:1693: Enum."-map/2-lists^map/1-1-"/2
    (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:1164: Ecto.Adapters.SQL.execute_ddl/4
    (ecto_sql 3.11.1) lib/ecto/migration/runner.ex:348: Ecto.Migration.Runner.log_and_execute_ddl/3
    (elixir 1.15.7) lib/enum.ex:1693: Enum."-map/2-lists^map/1-1-"/2
    (ecto_sql 3.11.1) lib/ecto/migration/runner.ex:311: Ecto.Migration.Runner.perform_operation/3
    (stdlib 5.1.1) timer.erl:270: :timer.tc/2
    (ecto_sql 3.11.1) lib/ecto/migration/runner.ex:25: Ecto.Migration.Runner.run/8

[joseustra]

I didn’t have the time to run the test multiple times, so I executed it one time before and one time after the change.

I have 7951 tests, many of which are LiveView tests.

From 362 to 353, about a 2.3% improvement in the value informed by ExUnit.

Before:

Finished in 362.2 seconds (356.1s async, 6.1s sync)	
________________________________________________________
Executed in  363.80 secs    fish           external
   usr time  505.12 secs    0.19 millis  505.12 secs
   sys time   85.99 secs    1.44 millis   85.99 secs


After:
Finished in 353.8 seconds (347.8s async, 6.0s sync)
________________________________________________________
Executed in  355.49 secs    fish           external
   usr time  500.29 secs    0.16 millis  500.29 secs
   sys time   86.22 secs    1.26 millis   86.22 secs

[greg-rychlewski]

This seems useful to me even if it makes tests slower. It is a feature of Postres so they had something in mind when they created it. And other people might discover their own uses outside of that. But like Jose said it's better if it's generalized to a string because all these modifiers exist:

CREATE [ [ GLOBAL | LOCAL ] { TEMPORARY | TEMP } | UNLOGGED ] TABLE

edit: oh I see you want to make a repo configuration too. then the test performance makes sense

[josevalim]

I agree we should support it as an option and as a string. I am not convinced on the repo configuration, given there is no meaningful gain, but perhaps we could introduce an option called :migration_table_options, which is more generic.

[mgibowski]

If I understand correctly, this would mean adding a new option to Ecto.Migration.table/2, right?

In that case, how should it be called?

For the reference - in Postgres docs it appears as Parameters, however Mysql and SQLlite don't give any name to that particular part of the create statement, they just call those options "keywords". Example from Sqllite:

If the "TEMP" or "TEMPORARY" keyword occurs between the "CREATE" and "TABLE" then the new table is created in the temp database.

The current options in Ecto.Migration.table/2 are:

    * `:primary_key` - when `false`, a primary key field is not generated on table
      creation. Alternatively, a keyword list in the same style of the
      `:migration_primary_key` repository configuration can be supplied
      to control the generation of the primary key field. The keyword list
      must include `:name` and `:type`. See `add/3` for further options.
    * `:engine` - customizes the table storage for supported databases. For MySQL,
      the default is InnoDB.
    * `:prefix` - the prefix for the table. This prefix will automatically be used
      for all constraints and references defined for this table unless explicitly
      overridden in said constraints/references.
    * `:comment` - adds a comment to the table.
    * `:options` - provide custom options that will be appended after the generated
      statement. For example, "WITH", "INHERITS", or "ON COMMIT" clauses. "PARTITION BY"
      can be provided for databases that support table partitioning.

We already have :options... How about calling it :parameters like in the Postgres docs?

    * `:parameters` - provide custom options that will be appended after the "CREATE" and before the "TABLE"
      statement. For example, "TEMPORARY", "UNLOGGED", "GLOBAL", or "LOCAL".

What do you think?

[josevalim]

:parameter is fine by me. :) Thanks for investigating!