Performance issue on filter

[jeremiedb]

As originally discussed in #2637

There appears to be some important performance deterioration when filtering on large datasets.

For example:

using DataFrames
df1 = DataFrame(rand(Int(2e6), 200));
function filter_df_1(df)
    df_f = filter(:x1 => x -> (x >= 0.1 && x <= 0.9), df)
    return df_f
end
@btime filter_df_1($df1);
 15.972 s (617 allocations: 2.40 GiB)

The computer resources/RAM seemed under control while performing the above:

However, the size of the resulting dataframe appears to have a great importance on the performance. If the filtering condition is restrained, the speed gets fine:

function filter_df_1(df)
    df_f = filter(:x1 => x -> (x >= 0.85 && x <= 0.9), df)
    return df_f
end
@btime filter_df_1($df1);
  168.308 ms (617 allocations: 154.34 MiB)

Does such behavior would have more to do on how Julia handles the memory / gc or the the actual DataFrames implementation? Comparative tests with R's data.table show no such latency issue when performing the same filtering.

DataFrames v0.22.5

julia> versioninfo()
Julia Version 1.5.3
Commit 788b2c77c1 (2020-11-09 13:37 UTC)
Platform Info:
  OS: Windows (x86_64-w64-mingw32)
  CPU: AMD Ryzen 7 4800HS with Radeon Graphics
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-9.0.1 (ORCJIT, znver2)

[bkamins]

I cannot reproduce it on Linux with 16GB of RAM:

julia> using DataFrames

julia> df1 = DataFrame(rand(Int(2e6), 200));

julia> function filter_df_1(df)
           df_f = filter(:x1 => x -> (x >= 0.1 && x <= 0.9), df)
           return df_f
       end
filter_df_1 (generic function with 1 method)

julia> @time filter_df_1(df1);
  2.159313 seconds (806.48 k allocations: 2.442 GiB, 21.76% gc time, 11.50% compilation time)

julia> @time filter_df_1(df1);
  1.711223 seconds (616 allocations: 2.396 GiB, 16.37% gc time)

julia> @time filter_df_1(df1);
  1.898099 seconds (616 allocations: 2.396 GiB, 22.56% gc time)

Having said that with #2647 you willl see big improvements here (just enable threading in Julia):

julia> using DataFrames

julia> df1 = DataFrame(rand(Int(2e6), 200), :auto);

julia> function filter_df_1(df)
           df_f = filter(:x1 => x -> (x >= 0.1 && x <= 0.9), df)
           return df_f
       end
filter_df_1 (generic function with 1 method)

julia> @time filter_df_1(df1);
  0.437730 seconds (1.84 k allocations: 2.394 GiB, 15.40% gc time)

julia> @time filter_df_1(df1);
  0.368338 seconds (1.84 k allocations: 2.394 GiB)

julia> @time filter_df_1(df1);
  0.619414 seconds (1.84 k allocations: 2.394 GiB, 37.70% gc time)

PS. Your code for DataFrame creation is deprecated, use :auto to auto-generate column names.

[bkamins]

I would close this unless you can see some problem with what I report (before benchmarking please make sure you have enough RAM to run the operations as 97% of GC time you report clearly means that you do not have enough RAM - maybe you are using some other applications in parallel that eat it up?).

[bkamins]

Ah - and regarding your plot - it seems RAM is not under control as it seems GC is run 3 times there.

[pdeffebach]

I can kind of replicate on Windows .

It takes me .6s on my linux partition, but 1s on my windows partition. But this is with a number of processes open.

Not sure how to do that graph on windows to check gc, though. I will explore more.

[bkamins]

Ah - OK. I will check on Windows then as I tested on Linux.

[bkamins]

This is on Windows the same machine:

julia> using DataFrames

julia> df1 = DataFrame(rand(Int(2e6), 200));

julia> function filter_df_1(df)
                  df_f = filter(:x1 => x -> (x >= 0.1 && x <= 0.9), df)
                  return df_f
              end
filter_df_1 (generic function with 1 method)

julia> @time filter_df_1(df1);
  1.786616 seconds (743.95 k allocations: 2.438 GiB, 24.96% gc time, 13.95% compilation time)

julia> @time filter_df_1(df1);
  1.245082 seconds (616 allocations: 2.396 GiB, 20.44% gc time)

julia> @time filter_df_1(df1);
  1.468204 seconds (616 allocations: 2.396 GiB, 28.53% gc time)

so it is the same.

Not sure how to do that graph on windows to check gc

Just use @time as I do above. You will get % of gc time. @jeremiedb - could you report your timings using @time?

[jeremiedb]

Here's what I got for the above test:

julia> @time filter_df_1(df1);
  1.825049 seconds (1.19 M allocations: 2.455 GiB, 29.43% gc time)

julia> @time filter_df_1(df1);
  2.882475 seconds (618 allocations: 2.396 GiB, 7.63% gc time)

julia> @time filter_df_1(df1);
  2.754756 seconds (618 allocations: 2.396 GiB, 23.78% gc time)

On another session, it then got better:

julia> @time filter_df_1(df1);
  1.881246 seconds (614.30 k allocations: 2.426 GiB, 14.77% gc time)

julia> @time filter_df_1(df1);
  1.164096 seconds (618 allocations: 2.396 GiB, 20.38% gc time)

I agree all this points that the drop in performance is closely tied to situation when RAM is under pressure. Yet data.table seems handle a little better those situations:

library(data.table)
x1 = data.table(matrix(runif(2e6 * 200), nrow=2e6))
> system.time(x1[V22 >= 0.1 & V22 <= 0.9])
   user  system elapsed 
   1.39    1.53    0.41 

Anyhow, I'm unclear whether there's anything specific to DataFrames.jl worth keeping this open if it's just a matter of how the OS or Julia and the OS manage memory?

[pdeffebach]

I think you should make an MWE that doesn't involve dataframes. Something like

julia> x = [rand(100) for i in 1:10];

julia> function get_subset(x)
           x1 = x[1]
           inds = broadcast(t -> t > .1 && t < .9, x1)
           return [xi[inds] for xi in x]
       end;

julia> get_subset(x);

Then see if you can narrow down the error and report it to the main Julia repo.

[jeremiedb]

Thanks for the help!

[bkamins]

I will keep it open until you can run the example given by @pdeffebach, but from what you report it is clearly related to how Julia manages memory and not DataFrames.jl.

[jeremiedb]

Performance appears fine with the the get_subset function:

x = [rand(2_000_000) for i in 1:200];
julia> @time get_subset(x);
  1.145908 seconds (405 allocations: 2.384 GiB, 42.62% gc time)
julia> @btime get_subset($x);
  968.530 ms (405 allocations: 2.38 GiB)

But rerunning the dataframe filter (2M rows / 200 cols) also resulted in little better perf than last time:

julia> @time filter_df_1(df1);
  1.419850 seconds (618 allocations: 2.398 GiB, 38.17% gc time)

julia> @btime filter_df_1($df1);
  1.227 s (618 allocations: 2.40 GiB)

There's still some overhead shown on dataframes vs subset, but the difference is definitely not problematic as the one first reported. One difference on this test run was that the committed memory was lower, at around 30Gb/50Gb, whereas when I first reported the performance, it was around 50Gb/58Gb.

On a different Linux machine, I also get some gap between the two:

julia> @btime get_subset($x);
  489.253 ms (405 allocations: 2.38 GiB)

julia> @btime filter_df_1($df1);
  634.932 ms (617 allocations: 2.40 GiB)

julia> size(x)
(200,)
julia> size(x[1])
(2000000,)
julia> size(df1)
(2000000, 200)

Unless you think the ~25% performance gap between get_subset and filter_df_1 is weird, I guess the wild timing swings has more to do with Windows mem management?

[bkamins]

These timings will be improved in #2647.

[pdeffebach]

Do we know what the cause of this is, though? I don't have any intuition for why we would see a performance difference without multi-threading. I can replicate the 25% preformance gap.

Does it really take 200ms to deal with column names and the Index object?