Postgresql Ecto query speed

audunfr · November 27, 2017, 10:23am

Hi. Not sure if this is the correct thread for this question, or its not really a question either, but lets try.

I have a simple user table in postgresql generated from Ecto migrate.
It contains a id, username, password, profile_picture, email phone and last coordinates geom).
When querying postgres directly with select [all fields] from users; it respond with 0,4xx ms.
When doing Repo.all User the iex is reporting a 35 to 40 ms query time.
While i do have other tables i see the same result on them, just using User since its familiar concept for all.

Is this the “normal” query time for ecto or do i have some optimization i could do?

Hardware is i5 3Ghz and 8Gb ram + SSD so should be good hardware. Db and Elixir is running on the same machine.

mbuhot · November 27, 2017, 10:34am

How does that time compare with a trivial query, such as Repo.query("select 1")
With postgres 10 running in docker, I get: [debug] QUERY OK db=2.4ms

outlog · November 27, 2017, 10:35am

It doesn’t sound normal - but we are also missing a lot of info… is it identical query, do you have proper indexes, is the image a blob etc?

If you post the raw sql query and the Repo.all query we can most likely be of better help

audunfr · November 27, 2017, 11:08am

Sure, i can post some more information. Guessed it was a little information but wanted to keep the post as clean as possible. The table users does only contain one row for the moment.

Database structure is the following:

 create table(:users) do
      add :name, :string, size: 100
      add :profile_picture, :string
      add :email, :string, size: 120
      add :phone, :string, size: 20
      add :bio, :string
      add :username, :string, size: 40
      add :password_hash, :string, size: 250
      add :geom, :geometry
      timestamps()
    end
    create unique_index(:users, [:username])
    create unique_index(:users, [:email])
    create index(:users, [:username, :password_hash])

psql > SELECT u0."id", u0."name", u0."profile_picture", u0."email", u0."phone", u0."bio", u0."username", u0."password_hash", u0."fb_uid", u0."geom", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE u0.id = 1; > ( 1 row ) Time: 0,531 ms

iex(8) Pb.Repo.get!(Pb.User, 1) [info] Processed SELECT u0."id", u0."name", u0."profile_picture", u0."email", u0."phone", u0."bio", u0."username", u0."password_hash", u0."fb_uid", u0."geom", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE (u0."id" = $1) in 37 ms

iex(9) Pb.Repo.query("SELECT * FROM users WHERE users.id = 1") [info] Processed SELECT * FROM users WHERE users.id = 1 in 37 ms

Software: Erlang 20 - Elixir 1.6.0-dev (same result on the 1.5 versions). Latest phoenix. OS: Centos 7, Postgresql 9.5 (9.6 also tested with same result)

benwilson512 · November 27, 2017, 11:27am

What versino of ecto / postgres are you using? The speeds reported by postgrex look like:

[debug] QUERY OK source="readings" db=0.2ms

Can you provide the exact output?

It would also be nice if you used code formatting in your posts to facilitate easy reading by those trying to help.

outlog · November 27, 2017, 11:30am

yeah, seems funky…

are you connecting to the db in the same way in psql/ecto eg. same hostname, are you using docker etc.

also what happens if you run Pb.Repo.get!(Pb.User, 1) a few times… A cold query can take some time, I just ran whatever I had in my iex history from yesterday:

[debug] QUERY OK source="bookings" db=64.9ms decode=0.9ms queue=0.1ms

and then after a few runs (identical query) it’s down to:

[debug] QUERY OK source="bookings" db=0.7ms

benwilson512 · November 27, 2017, 12:01pm

Ah yeah @outlog makes a great point. Make sure to run the query a time or two first before actually looking at the time. In Mix, code isn’t loaded until its module is actually called. This means that the first time you do anything it takes longer because it has to load the code.

audunfr · November 27, 2017, 12:06pm

Hi @benwilson512 and @outlog.

I’m adding all the output i’m getting. Dont know why i do not get the [debug] entry you guys are getting.

The machine is all metal and no virtualization is used. The postgresql database version is 9.5, but as stated above 9.6 and also 10 is giving the same query results. Both ecto and psql is connecting using the same user, same hostname etc.
Ecto version i’m not 100% sure as i cannot find a ecto --version look a like command, but all docs is pointing to 2.2.6

I’ve runned the commands multiple times in both psql and ecto to ensure the result is the same, also in different iex sessions to be sure i get the same result.

Sorry for the code formatting. Not sure how i get that to work, but got it to work on the model in the post above.

benwilson512 · November 27, 2017, 12:19pm

Code formatting can be accomplished via use of ``` before and after text like so:

```
foo
```
ends up looking like:

foo

You can determine the versions of your dependencies via doing mix deps

audunfr · November 27, 2017, 12:21pm

Knew it was something simple to get the version, just could not figure it out. :-).

mix deps gives me

phoenix_ecto 3.3.0
ecto 2.2.6

outlog · November 27, 2017, 12:43pm

the db is local right? try 127.0.0.1 so there is absolutely no network funkiness

can you post the migration so I can attempt to reproduce…

audunfr · November 27, 2017, 2:03pm

The DB is local (at the same machine) as Phoenix(Elixir). Changing from Localhost to 127.0.0.1 did not change the results

Migration

def change do

    create table(:users) do
      add :name, :string, size: 100
      add :profile_picture, :string
      add :email, :string, size: 120
      add :phone, :string, size: 20
      add :bio, :string
      add :username, :string, size: 40
      add :password_hash, :string, size: 250
      timestamps()
    end
    create unique_index(:users, [:username])
    create unique_index(:users, [:email])
    create index(:users, [:username, :password_hash])
 end

Model:

defmodule Pb.User do
  use Pb.Web, :model
  import Comeonin.Bcrypt


  schema "users" do
    field :name, :string, size: 100
    field :profile_picture, :string
    field :email, :string, size: 120
    field :phone, :string, size: 20
    field :bio, :string
    field :username, :string, size: 40
    field :password_hash, :string, size: 100
    field :password, :string, virtual: true
    field :fb_uid, :string
    field :geom, Geo.Geometry
    timestamps()
  end

  def changeset(struct, params \\ %{}) do
    struct
    |> cast(params, [:username, :password_hash, :email, :profile_picture, :bio, :name, :fb_uid, :geom])
    |> unique_constraint(:email)
    |> unique_constraint(:username)
    |> validate_format(:email, ~r/@/)
    |> validate_required([:username])
  end
  def register_changeset(struct, params \\ %{}) do
    struct             # do other standard validations
    |> cast(params, [:username, :password, :profile_picture])          
    |> validate_length(:password, min: 5) # validations
    |> validate_length(:username, min: 3)
    |> unique_constraint(:email)
    |> unique_constraint(:username)
    |> put_pass_hash()
  end
def put_pass_hash(changeset) do
      changeset
      |> put_change(:password_hash, Pb.User.hash_password(changeset.params["password"]))
  end

 def hash_password(password) do
    hashpwsalt(password)
  end

end

outlog · November 27, 2017, 2:38pm

field :geom, Geo.Geometry

is not in the migration… and that would one would be my number 1 candidate if there really is a reproducible slow down. So please add that one, or even better create a github repo with a reproducible phoenix app (eg I’m left to assume Geo.Geometry is from the “geo” package etc)

also how fast is Pb.Repo.get(Pb.User, 0), and if you comment out field :geom, Geo.Geometry in the schema does that change anything…

audunfr · November 27, 2017, 2:58pm

Yea, sorry. The :geom was in an additional migration that i missed to copy in and is from the geo package.
I uncommented it in the model to check if the speed changed, and it did not. Same result.

I cannot share the source code due to company rules, but let me see if i can create a new phoenix app with the exact models and have that a public repo.

Stay tuned

OvermindDL1 · November 27, 2017, 5:46pm

When querying postgres directly with select [all fields] from users; it respond with 0,4xx ms.

That is the internal postgreql server speed, not necessarily any of the socket communication and memory allocation.

When doing Repo.all User the iex is reporting a 35 to 40 ms query time.

Most of my ecto queries take between 1-20ms, most are on the low end, very few (mostly big reports) on the high end (with a couple taking a couple hundred ms, though that is expected for those). Raw roundtrip no-op time average 0.7ms. All of these times are after the query is cached, you should never really look at the uncached times.

audunfr · November 28, 2017, 5:24am

Yea, get the same results as you OvermindDL1 when running locally on my MacBook (Postgresql locally). First request is high at around 50ms, but all later queries clocks in at about 4-9ms.

The only difference between my local machine is i7(lower speed than prod server) and 16Gb memory(8 in prod server) and Postgresql 10. I’ve tried Postgresql 10 at the production server and does not help, so guess its not that.

Will create a test project during the day and test it out on the production server and publish to a GitHub repo.

audunfr · December 1, 2017, 1:37pm

Just a note. The prod server we where using got reinstalled for a unknown reason.
When everyting was installed again ( same setup as before ) i get decent query speeds again.

First request for a user = 30ms, all queries after the first load is ± 8 ms.

Thats a good number and i cannot reproduce the high numbers i had before so unsure how to debug this furter.
Must have been a software error somewhere or something, i dont know.

audunfr · December 4, 2017, 9:25am

Also want to add that the reinstalled software was now installed on FreeBSD 11.1, was CentOS 7 before. Not that i think it makes a huge difference.

Most of my endpoints where laying at 250-500 ms from Postman before.
Now many of them have gone from 300+ms to ~30ms in response time.
The server is the same, network is the same, test client is the same but server OS has changed and both DB and OTP, Elixir and Phoenix reinstalled.

marat · December 20, 2018, 11:39am

Reinitializing the topic: same problem with Postgres/Ecto.

    create table(:merchant_transactions) do
      add :merchant_id, :integer
      add :transaction_id, :integer
      add :usd_amount, :decimal
      add :trans_amount, :decimal
      add :trans_currency_code, :string
      add :trans_date, :naive_datetime
      add :trans_created_at, :naive_datetime
      add :trans_updated_at, :naive_datetime

      timestamps()
    end
    create index("merchant_transactions", [:merchant_id])
    create index("merchant_transactions", [:inserted_at])
    create index("merchant_transactions", [:trans_date])

Model:

  schema "merchant_transactions" do
    field :merchant_id, :integer
    field :transaction_id, :integer
    field :usd_amount, :decimal
    field :trans_amount, :decimal
    field :trans_currency_code, :string
    field :trans_date, Timex.Ecto.DateTime
    field :trans_created_at, Timex.Ecto.DateTime
    field :trans_updated_at, Timex.Ecto.DateTime

    timestamps([autogenerate: {Timex, :now, []}])
  end

  def transactions_after_date(date) do
    from m in MerchantTransaction,
         where: m.trans_date > ^date
  end

Query:

    options = %{time_term: "months", time_value: -1, grouping: "sum"}
    now = Timex.now
    hour_ago = Timex.shift(now, [{String.to_atom(options.time_term), options.time_value}])
    {:ok, str_hour_ago} = Timex.format(hour_ago, "{ISO:Extended:Z}")

    transactions = MerchantTransaction.transactions_after_date(str_hour_ago) |> Markers.Repo.all

When called in iex the last line is executed in 300-500ms:

:timer.tc(fn ->     transactions = MerchantTransaction.transactions_after_date(str_hour_ago) |> Markers.Repo.all end) |> elem(0)
[debug] QUERY OK source="merchant_transactions" db=453.7ms decode=172.6ms
SELECT m0."id", m0."merchant_id", m0."transaction_id", m0."usd_amount", m0."trans_amount", m0."trans_currency_code", m0."trans_date", m0."trans_created_at", m0."trans_updated_at", m0."inserted_at", m0."updated_at" FROM "merchant_transactions" AS m0 WHERE (m0."trans_date" > $1) [{{2018, 2, 20}, {10, 36, 0, 624233}}]
630562

iex(28)> :timer.tc(fn ->     transactions = MerchantTransaction.transactions_after_date(str_hour_ago) |> Markers.Repo.all end) |> elem(0)
[debug] QUERY OK source="merchant_transactions" db=403.6ms decode=145.7ms
SELECT m0."id", m0."merchant_id", m0."transaction_id", m0."usd_amount", m0."trans_amount", m0."trans_currency_code", m0."trans_date", m0."trans_created_at", m0."trans_updated_at", m0."inserted_at", m0."updated_at" FROM "merchant_transactions" AS m0 WHERE (m0."trans_date" > $1) [{{2018, 2, 20}, {10, 36, 0, 624233}}]
552560

iex(29)> :timer.tc(fn ->     transactions = MerchantTransaction.transactions_after_date(str_hour_ago) |> Markers.Repo.all end) |> elem(0)
[debug] QUERY OK source="merchant_transactions" db=245.1ms decode=127.9ms
SELECT m0."id", m0."merchant_id", m0."transaction_id", m0."usd_amount", m0."trans_amount", m0."trans_currency_code", m0."trans_date", m0."trans_created_at", m0."trans_updated_at", m0."inserted_at", m0."updated_at" FROM "merchant_transactions" AS m0 WHERE (m0."trans_date" > $1) [{{2018, 2, 20}, {10, 36, 0, 624233}}]
375806

iex(30)> :timer.tc(fn ->     transactions = MerchantTransaction.transactions_after_date(str_hour_ago) |> Markers.Repo.all end) |> elem(0)
[debug] QUERY OK source="merchant_transactions" db=228.7ms decode=292.4ms
SELECT m0."id", m0."merchant_id", m0."transaction_id", m0."usd_amount", m0."trans_amount", m0."trans_currency_code", m0."trans_date", m0."trans_created_at", m0."trans_updated_at", m0."inserted_at", m0."updated_at" FROM "merchant_transactions" AS m0 WHERE (m0."trans_date" > $1) [{{2018, 2, 20}, {10, 36, 0, 624233}}]
526772

Direct call in psql is very fast:

explain analyze SELECT m0."id", m0."merchant_id", m0."transaction_id", m0."usd_amount", m0."trans_amount", m0."trans_currency_code", m0."trans_date", m0."trans_created_at", m0."trans_updated_at", m0."inserted_at", m0."updated_at" FROM "merchant_transactions" AS m0 WHERE (m0."trans_date" > '2018-02-20 10:36:00.624233');
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Seq Scan on merchant_transactions m0  (cost=0.00..491.24 rows=17379 width=610) (actual time=0.009..4.742 rows=17379 loops=1)
   Filter: (trans_date > '2018-02-20 10:36:00.624233'::timestamp without time zone)
 Planning time: 0.150 ms
 Execution time: 6.082 ms
(4 rows)

Even if I call the query directly like

SELECT m0."id", m0."merchant_id", m0."transaction_id", m0."usd_amount", m0."trans_amount", m0."trans_currency_code", m0."trans_date", m0."trans_created_at", m0."trans_updated_at", m0."inserted_at", m0."updated_at" FROM "merchant_transactions" AS m0 WHERE (m0."trans_date" > '2018-02-20 10:36:00.624233');

the resulting out put is shown very fast. I understand that it’s not taking full set at once, and no elixir decoding, but still: why is that SO long? half a second!

Resulting data set is 17379 rows, is that a problem?

Postgres and Iex are running on same machine locally, without docker.

Tried config with localhost and 127.0.0.1 - same result.

Any clues?
Thanks!

voughtdq · December 20, 2018, 12:07pm

What happens when you select only these rows: [:merchant_id, :transaction_id, :usd_amount, :trans_amount, :trans_currency_code]. Do you notice any change in speed?