join operation almost 2 times slower

[vk111]

HI, I was testing
data.table_1.10.4-3 + R version 3.4.0 (2017-04-21)
vs
data.table_1.12.2 + R version 3.6.1 (2019-07-05)

and have noticed that join operation almost 2 times slower in new version data.table (R?)
I think mostly depends on version of data.table

rm(list=ls())

library(data.table)
library(tictoc)


aa = data.table(a = seq(1,100), b = rep(0, 100))
bb = data.table(a = seq(1,100), b = rep(1, 100))

#aa[,  a1 := as.character(a)]
#bb[,  a1 := as.character(a)]

setindex(aa, a)
setindex(bb, a)

tic()
for(i in c(1:1000)) {
 # aa[bb, b := i.b, on=.(a, a1)] # test1
  aa[bb, b := i.b, on=.(a)] # test2
}
toc()

# test1
# 3.6.1: 5.5 sec with index
# 3.6.1: 6.87 sec without index
# 3.4.0: 3.02 sec (no index)

# test2
# 3.6.1: 3.82 sec with index
# 3.6.1: 4.44 sec without index
# 3.4.0: 2.48 sec (no index)

[MichaelChirico]

Have run the following:

# run_join_time.sh
echo 'hash,time' > 'join_timings.csv'

for HASH in $(git rev-list --ancestry-path 1.10.0..1.12.4 | awk 'NR == 1 || NR % 10 == 0');
do git checkout $HASH && R CMD INSTALL . && Rscript time_join.R $HASH;
done

# time_join.R
library(data.table)
library(microbenchmark)

hash = commandArgs(trailingOnly = TRUE)

aa = data.table(a = seq(1,100), b = rep(0, 100))
bb = data.table(a = seq(1,100), b = rep(1, 100))

fwrite(data.table(
  hash = hash,
  time = microbenchmark(times = 1000L, aa[bb, b := i.b, on=.(a)])$time
), 'join_timings.csv', append = TRUE)

Then did the following to create this plot

library(data.table)
times = fread('join_timings.csv')

times[ , date := as.POSIXct(system(sprintf("git show --no-patch --no-notes --pretty='%%cd' %s", .BY$hash), intern = TRUE), by = hash]
times[ , date := as.POSIXct(date, format = '%a %b %d %T %Y %z', tz = 'UTC')]
times[ , date := as.IDate(date)]
setorder(times, date)

tags = system('
for TAG in $(git tag);
  do git show --no-patch --no-notes --pretty="$TAG\t%cd" $TAG;
done
', intern = TRUE)

tags = setDT(tstrsplit(tags, '\t'))
setnames(tags, c('tag', 'date'))
tags[ , date := as.POSIXct(date, format = '%a %b %d %T %Y %z', tz = 'UTC')]
tags[ , date := as.IDate(date)]

times[ , {
  par(mar = c(7.1, 4.1, 2.1, 2.1))
  y = boxplot(I(time/1e6) ~ date, log = 'y', notch = TRUE, pch = '.',
              las = 2L, xlab = '', ylab = 'Execution time (ms)', cex.axis = .8)
  x = unique(date)
  idx = findInterval(tags$date, x)
  abline(v = idx[idx>0L], lty = 2L, col = 'red')
  text(idx[idx>0L], .7*10^(par('usr')[4L]), tags$tag[idx>0L], 
       col = 'red', srt = 90)
  NULL
}]

---

After starting I realized I could streamline this a bit by using

echo 'hash,time,date' > 'join_timings.csv'

for HASH in $(git rev-list --ancestry-path 1.10.0..1.12.4 | awk 'NR == 1 || NR % 10 == 0');
do git checkout $HASH && R CMD INSTALL . --preclean && Rscript time_join.R $HASH $(git show --no-patch --no-notes --pretty='%cd' $HASH);
done

library(data.table)
library(microbenchmark)

args = commandArgs(trailingOnly = TRUE)
hash = args[1L]
date = as.POSIXct(args[2L], format = '%a %b %d %T %Y %z', tz = 'UTC'))

aa = data.table(a = seq(1,100), b = rep(0, 100))
bb = data.table(a = seq(1,100), b = rep(1, 100))

fwrite(data.table(
  hash = hash,
  date = date,
  time = microbenchmark(times = 1000L, aa[bb, b := i.b, on=.(a)])$time
), 'join_timings.csv', append = TRUE)

to add the commit time directly to the benchmark

join_timings.txt

[vk111]

Hi MichaelChirico, I have read twice
but what does exactly mean the timeline from 2016 to 2019? Is it a version of datatable?

[MichaelChirico]

not just versions but specific commits. let me try and add some demarcation of versions, a good idea I forgot to add in

[jangorecki]

@MichaelChirico your graph looks super cool, what was missing was an interpretation of that :) By guessing I would say that new parallel forder is slower for an input of length 100 than it was before. Which IMO is fine, because these are still microseconds. It is of course worth to reduce the overhead but the priority should be a reduction of resources in the most common usage scenarios. Looping 10000 times on a length 100 input is definitely not one of those.

[MichaelChirico]

that was my guess too after looking at the 1.12.0 NEWS. will try re running single threaded.

[vk111]

@jangorecki, if you do the simple math it's thousands of microseconds ie milliseconds
The inspiration of this test was my current project where I join 7-8 times tables with 40 000 rows
Before it takes 18 seconds, after it takes 40 seconds
My test also includes character key
I installed 3.6+1.12 and then rolled it back to 3.4+1.10
I think this is not normal situation that's why this issue is here

[mattdowle]

Yes the graph is really awesome; we should do more of this and automate it.

But the original report compares R 3.4 to R 3.6, which has R 3.5 in the middle. We know that R 3.5 impacted data.table via ALTREP's change of REAL(), INTEGER() from macros to (slightly heavier) functions.

@vk111 Can you please rerun your tests with v1.12.4 now on CRAN. Any better? We have been taking R API outside loops to cope with R 3.5+. As the next step, it would be great to know how you find v1.12.4. Can you also include more information about your machine; e.g operating system, RAM and number of CPU.

[vk111]

@matt, will do

[vk111]

Hi @mattdowle ,

Ive updated to 1.12.4 (+R 3.6.1) - basically there are the same numers for unit test and my func
I will consider here only joins with character without indexing - as a benchmark
Unit test (as mentioned in the first post)
3.6.1: 6.87 sec without index
3.4.0: 3.02 sec (no index)

My function from project remains the same: 20 vs 40 seconds
It consists only ~14 dt joins
two tables 30 000 rows (dt1) and 366 000 rows (dt2)
15 columns each
key is 2 characters and 1 numeric
and assigned 7 fields (from dt1 to dt2) during the join

my PC:
Win 10 64 bit
AMD A8 2.2 Ghz
8 Gb RAM

cmd: wmic cpu get NumberOfCores, NumberOfLogicalProcessors/Format:List
NumberOfCores=4
NumberOfLogicalProcessors=4

Thank you for your analysis

[vk111]

Hi @mattdowle so are you considering this?

[MichaelChirico]

According to a git bisect I just re-ran, this commit is "guilty" for the slow-down, hopefully that can help Matt pin down the root. That it's related to forder makes me relatively confident we've pinned it down correctly.

e59ba14

More precisely:

# run_join_time.sh
R CMD INSTALL . && Rscript time_join.R

# time_join.R
library(data.table)
library(microbenchmark)

aa = data.table(a = seq(1,100), b = rep(0, 100))
bb = data.table(a = seq(1,100), b = rep(1, 100))

summary(microbenchmark(times = 1000L, aa[bb, b := i.b, on=.(a)])$time/1e6)

With these two scripts, from master/HEAD:

git checkout 1.12.0
git bisect start
git bisect bad
git bisect good 1.11.8

Then at each iteration, run sh run_join_time.sh and check the result. The bad commits were taking roughly .9 seconds per iteration on my machine, good commits about .7.

[vk111]

Hi Michael, thank you, but performance has dropped dramatically especially for character key-I provided with the unit test in the very first post Anyway I think we need to wait confirmation from Matt whether it’s fixed in new version or not

On Thu, 26 Dec 2019 at 15:02, Michael Chirico ***@***.***> wrote: According to a git bisect I just re-ran, this commit is "guilty" for the slow-down, hopefully that can help Matt pin down the root. That it's related to forder makes me relatively confident we've pinned it down correctly. e59ba14 <e59ba14> More precisely: # run_join_time.sh R CMD INSTALL . && Rscript time_join.R # time_join.R library(data.table) library(microbenchmark) aa = data.table(a = seq(1,100), b = rep(0, 100)) bb = data.table(a = seq(1,100), b = rep(1, 100)) summary(microbenchmark(times = 1000L, aa[bb, b := i.b, on=.(a)])$time/1e6) With these two scripts, from master/HEAD: git checkout 1.12.0 git bisect start git bisect bad git bisect good 1.11.8 Then at each iteration, run sh run_join_time.sh and check the result. The bad commits were taking roughly .9 seconds per iteration on my machine, good commits about .7. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#3928?email_source=notifications&email_token=ABRM7MJQITNUZDNYV7NTIX3Q2S2ORA5CNFSM4I4ZPREKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHVTR4Q#issuecomment-569063666>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABRM7MOTZRFFM2QKVFUHT6LQ2S2ORANCNFSM4I4ZPREA> .

-- Best regards, Vasily Kuznetsov