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?

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.

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