janhendrik-rust
Ecto connection times out when using TDS adapter to query MSSQL database
I have a table with several columns of floating point numbers in a MSSQL 2019 database.
When I try to naively query all the rows in the table the connection times out with an arror
Tds.Protocol (#PID<0.621.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.677.0> timed out because it queued and checked out the connection for longer than 5000ms
Eventually the data is returned, but I am concerned that it takes 2000x longer with the Tds adapter than with the Postgres adapter.
I have created a demo repo that seeds some data and can be used to easily see the performance difference:
(GitHub - janhendrik-rust/slow_going)[GitHub - janhendrik-rust/slow_going]
The postgres and odbc connections complete the query and return in under 50ms, the Tds adapter takes over 90 seconds on the same size dataset.
Is there a better way to query medium sized datasets using Ecto connecting to a MSSQL server? Or do I have something missing in my configuration?
Marked As Solved
mjaric
The issue is at line 508 in Tds.Types module, just comment it out and it should fly 
data_type_code == @tds_data_type_floatn ->
data = data <> tail
len = length * 8
<<val::little-float-size(len), _::binary>> = data
val
should be
data_type_code == @tds_data_type_floatn ->
len = length * 8
<<val::little-float-size(len)>> = data
val
Also Liked
al2o3cr
I don’t know the TDS protocol well enough to be sure this is the issue, but one innocuous-seeming line in the type-conversion code is a performance black-hole:
tds/lib/tds/types.ex at f15b86871c41d004345d20130e0db215f03dc78a · elixir-ecto/tds · GitHub
Reattaching data to tail is potentially VERY expensive if tail is the next 10k rows!
I wrote a microbenchmark to demonstrate this:
defmodule Bench do
def from_tds(<<>>), do: nil
def from_tds(<<size::unsigned-8, data::binary-size(size), tail::binary>>) do
data = data <> tail
<<val::little-float-size(64), _::binary>> = data
{val, tail}
end
def shorter_version(<<>>), do: nil
def shorter_version(<<size::unsigned-8, data::binary-size(size), tail::binary>>) do
<<val::little-float-size(64)>> = data
{val, tail}
end
def big_binary(size) do
<<8, 0, 0, 0, 0, 0, 0, 0, 0>>
|> List.duplicate(size)
|> Enum.join()
end
def run_example(size, fun) do
big_binary(size)
|> Stream.unfold(fun)
|> Stream.run()
end
end
[100, 1000, 10_000, 100_000, 1_000_000]
|> Enum.each(fn size ->
{from_tds_time, _} = :timer.tc(&Bench.run_example/2, [size, &Bench.from_tds/1])
{shorter_version_time, _} = :timer.tc(&Bench.run_example/2, [size, &Bench.shorter_version/1])
IO.puts("#{size}:\t#{from_tds_time}\t#{shorter_version_time}\t#{from_tds_time / shorter_version_time}")
end)
Here are the results from my local machine (Elixir 1.13, 2015 MBP):
100: 6250 22 284.09090909090907
1000: 1583 147 10.768707482993197
10000: 28594 1791 15.965382467895031
100000: 37877514 28739 1317.983019590104
1000000: (I got bored)
That seems to echo the way you’re seeing query times scale with size.
As to fixing the issue, I don’t know the TDS protocol at all. Are there situations where length (from the column metadata) and size (from the binary stream) would disagree?
janhendrik-rust
That is exactly right, when I profile an integers only query
from(f in FloatsTest, select: [f.int_one, f.int_two, f.int_three, f.int_four, f.int_five, f.int_six, f.int_seven, f.int_eight, f.int_nine], limit: 10000) |> Repo.all()
The query returns in 7 seconds instead of 52 seconds
CNT ACC (ms) OWN (ms)
Total 913951 7469.975 7287.849
:fprof.apply_start_stop/4 0 7469.975 0.032
anonymous fn/0 in :elixir_compiler_1.__FILE__/1 1 7469.943 0.008
SlowGoing.Run.fetch_all_ints/0 1 7469.935 0.022
SlowGoing.Repo.all/1 1 7469.867 0.005
SlowGoing.Repo.all/2 1 7469.862 0.022
Ecto.Repo.Queryable.all/3 1 7469.682 0.023
Ecto.Repo.Queryable.execute/4 1 7469.627 0.065
Enum.map/2 5 4632.802 0.026
Enum."-map/2-lists^map/1-0-"/2 20005 4632.776 286.250
Ecto.Repo.Preloader.query/6 1 4388.941 0.012
anonymous fn/3 in Ecto.Repo.Queryable.postprocessor/4 10000 4242.289 91.559
Ecto.Repo.Queryable.process/4 100000 4148.128 881.984
Ecto.Repo.Queryable.process_args/4 10000 4091.856 56.506
Enum.map_reduce/3 10007 4034.502 56.159
Enum."-map_reduce/3-lists^mapfoldl/2-0-"/3 100007 3977.243 1324.443
Ecto.Adapters.Tds.execute/5 1 2835.755 0.006
Ecto.Adapters.SQL.execute/6 1 2835.749 0.014
Ecto.Adapters.SQL.execute!/5 1 2835.730 0.009
Ecto.Adapters.SQL.sql_call/5 1 2835.721 0.031
Ecto.Adapters.Tds.Connection.execute/4 1 2835.655 0.024
DBConnection.prepare_execute/4 1 2835.503 0.024
DBConnection.parsed_prepare_execute/5 1 2830.201 0.017
DBConnection.run/6 1 2690.386 0.023
DBConnection.run_prepare_execute/5 1 2689.441 0.016
DBConnection.Holder.handle/4 2 2689.278 0.013
DBConnection.Holder.handle_or_cleanup/5 2 2689.265 0.029
DBConnection.Holder.holder_apply/4 2 2689.215 0.038
Tds.Protocol.msg_send/2 3 2687.875 0.136
DBConnection.run_execute/5 1 2685.452 0.014
Tds.Protocol.handle_execute/4 1 2684.381 0.037
Tds.Protocol.send_query/2 1 2682.710 0.008
Tds.Protocol.decode/2 3 2671.407 0.046
Tds.Messages.parse/3 3 2671.237 0.071
anonymous fn/4 in Ecto.Repo.Queryable.process_args/4 90000 2602.208 503.440
Tds.Tokens.decode_tokens/1 3 2526.041 0.016
Tds.Tokens.decode_tokens/2 10012 2526.025 141.649
Tds.Tokens.decode_row/2 10000 2379.666 92.614
Tds.Tokens.decode_row_columns/2 10000 2282.176 55.985
Tds.Tokens.decode_row_columns/3 100000 2224.965 1056.610
Ecto.Type.adapter_load/3 90000 1229.861 819.005
Tds.Tokens.decode_row_column/2 90000 1004.601 505.789
Tds.Types.decode_data/2 90001 465.631 404.840
Ecto.Type.of_base_type?/2 90000 385.967 378.347
Ecto.Repo.Assoc.query/4 1 243.853 0.006
:suspend 728 182.126 0.000
Enum.reduce/3 10 145.852 0.055
Enum."-reduce/3-lists^foldl/2-0-"/3 10038 145.817 100.787
Enum.reverse/1 10012 141.788 93.154
DBConnection.decode/4 1 139.798 0.019
DBConnection.Query.decode/3 1 139.760 0.014
DBConnection.Query.Tds.Query.decode/3 1 139.729 0.023
DBConnection.Query.Tds.Query.do_decode/3 10001 139.685 97.943
anonymous fn/3 in Ecto.Repo.Queryable.preprocessor/3 10000 95.830 54.176
:garbage_collect 340 95.473 95.473
:lists.reverse/2 10019 45.129 43.750
anonymous fn/2 in Tds.Messages.parse/3 10004 43.369 40.733
Ecto.Repo.Queryable.preprocess/4 10000 41.153 40.356
anonymous fn/1 in DBConnection.Query.Tds.Query.decode/3 10000 40.575 39.629
Tds.Protocol.msg_recv/1 3 13.435 0.071
Tds.Protocol.msg_recv/2 76 11.236 1.577
:gen_tcp.recv/2 76 10.032 0.814
:inet_tcp.recv/2 76 8.064 0.407
:prim_inet.recv/2 76 7.657 0.385
:prim_inet.recv0/3 76 7.272 0.714
DBConnection.log/4 1 5.217 0.006
DBConnection.log/5 1 5.211 0.022
DBConnection.log/2 1 5.044 0.008
... the rest of the profiler output is available at (https://github.com/janhendrik-rust/slow_going/wiki/Result-of-selecting-10000-Rows-by-9-columns-of-ints) ...
So it is deffinately the floating point codepath that has bad performance problems.
janhendrik-rust
Thanks SO MUCH @mjaric and @al2o3cr.
I’ve just tested this fix and selecting 10_000 rows of 9 floats went from 45.9 seconds down to 173ms, that is an awesome 260x speed improvement.
The GC also only kicks in 455 times instead of 68406 times.
These numbers are obviously specific to my tests on my machine and only relevant when querying ““lots”” of rows with floating point numbers. Regardless, the performace is still at least two orders of magnitude better than before this fix.
I’ve had a look at the types.ex file history and @naag removed the same tail append for tds_data_type_intn in 22cb46a.
In my tests the floats still come through with their full precision so I don’t see any negative effect on the returned dataset after commenting out line 508
sbuttgereit
Pretty sure it doesn’t; unless its third party… and even then not sure how (or why) you’d do it. I’m just about to start a gig helping with a MS SQL Server migration to PostgreSQL which includes a temporary integration piece. Connectivity mismatches is one of the issues which led to them brining me in. Lots of differences from authentication techniques, to data types, etc. not sure it would be feasible to make it work, let alone any reason/benefit at that level.
While the person you’re responding to would need to answer to be sure (naturally), I read their comment as, “2000x longer with Tds connecting to MSSQL server than the PostgreSQL adapter connecting to PostgreSQL.” (with against the same data implied).
If I get some time, and since I just happen to have a MSSQL Server setup on my workstation now due to this other project, I might try the repo the questioner posted to see if I can help; weekend stuff though, I’m afraid.
Popular in Questions
Other popular topics
Latest on Elixir Forum
Sponsor Spotlight
Supporting innovation across the BEAM ecosystem.
Categories:
Sub Categories:
Forums
Our Sponsors
Build Elixir applications with speed and confidence.
Supporting innovation across the BEAM ecosystem.
We build reliable cloud platforms for business-critical systems.
Catch errors, track performance, monitor hosts and more.
Practical resources that improve the lives of professional developers.
Develop your skills with books, videos, and courses.
Producing high quality Elixir screencasts since 2017.
Courses that'll move you from confusion to "Aha, now I get it!"