Add an atime performance regression test for forder caching

[MichaelChirico]

          @Anirban166 this is a good candidate for a performance regression test, would you like to take a stab at writing one? I don't think Jan will get to it quickly :)

Originally posted by @MichaelChirico in #4386 (comment)

It will be good to have a test in the performance suite showing the improvement + preventing regression.

[Anirban166]

Forgot to mention here or link back to this issue but I created a test shortly around the time after you posted this, GHA test in my fork - @MichaelChirico @tdhock Could you guys please check if that qualifies?

My code for quick reference:

...

  "forder improved in #4386" = atime::atime_test(
    N = 10^seq(1, 8), # 1e9 probably exceeds the runner's memory (process gets killed)
    setup = {
      dt <- data.table(id = sample(N), value = rnorm(N))
    },
    expr = {
      data.table:::setkey(dt, id)
      dt[order(data.table:::forder(dt, "id"))]
      dt[order(data.table:::forder(dt, "id"))] # Can repeat more but twice is good enough to see the caching in effect.
    },
    Slow = "c152ced0e5799acee1589910c69c1a2c6586b95d", # Parent of the merge commit that fixes the regression
    Fast = "1a84514f6d20ff1f9cc614ea9b92ccdee5541506"), # Merge commit of the PR (https://github.com/Rdatatable/data.table/pull/4386/commits) that fixes the regression

...

I was not sure if the test case I wrote above was accurate enough (compared to this say, since I didn't use datatable.forder.reuse.sorting=TRUE), but the results look about right to me: (clear spike in memory usage, all version labels seem to make sense)

[tdhock]

I dont see any time difference, only memory difference. is that normal?

[Anirban166]

Given the purpose of caching, the main improvement should be in time so I think you're right as this shows little difference there (the 'Slow' label is still above compared to the other versions) versus it indicating better use of memory by a higher factor.

[tdhock]

then your performance test needs to be revised

[Anirban166]

WDYT about the latest one? (to me, it makes much more sense than the previous results I was getting)

Core differences in this test case compared to my previous version include additional ordering operations, using setindex instead of setkey, and testing different key combinations to evaluate the performance of reusing the cache better.

[tdhock]

this new figure is not conclusive because we only see one N for most versions.
you could increase seconds.limit to debug, but you should revise the test case to get the overall timings for all methods well below 0.01 seconds, so the test case runs fast on CI.

[Anirban166]

this new figure is not conclusive because we only see one N for most versions.

True

I kept revising my test and played around with the parameters a bit till I found a sweet spot (minimal time ft. correct results) among the results that I'm observing:

...

  "forder improved in #4386" = atime::atime_test(
    ## 1e9 exceeds the runner's memory (process gets killed) and < 1e8 does not show the most accurate results for memory use.
    N = 10^seq(3, 8),
    seconds.limit = 0.08,
    setup = {
      dt <- data.table(a = sample(letters, N, TRUE))
    },
    expr = {
      data.table:::setindex(dt, a)  
      options(datatable.forder.reuse.sorting = TRUE, datatable.verbose = TRUE)
      dt[order(data.table:::forder(dt, "a"))]
      dt[order(data.table:::forder(dt, "a"))]
    },
    Slow = "c152ced0e5799acee1589910c69c1a2c6586b95d", # Parent of the merge commit that fixes the regression
    Fast = "1a84514f6d20ff1f9cc614ea9b92ccdee5541506"), # Merge commit of the PR (https://github.com/Rdatatable/data.table/pull/4386/commits) that fixes the regression

...

This runs for all N up to 10⁸ only when seconds.limit is greater than 0.07 seconds (else the computations for the higher N will be cut off like the previous plot I shared on this thread), thus 0.08. If I were to reduce computing N to 10⁷ or lower, we won't get accurate results ('Fast' and 'Slow' labels will be together in terms of memory for e.g. which I don't think is true, or it should show a difference/improvement in memory usage as well for an amply sized benchmark).

As for CI, the time difference in running this is not too big (~20 seconds more on average) vs the last one I shared here above or the usual time it takes to run this one test. Thoughts? @tdhock

[tdhock]

your figure does not make sense. Fast has larger computation time than Slow. Did you mix them up? Why is there such a large difference in the constant overhead? Please double check.

[tdhock]

it seems like this is taking too long and you are not making much progress, so maybe try to focus your time on other low hanging fruit? (other tasks which would be easier/faster to get useful results)

[Anirban166]

your figure does not make sense. Fast has larger computation time than Slow. Did you mix them up? Why is there such a large difference in the constant overhead? Please double check.

I thought the label grouping made sense..it's similar to some other test case results that you approved of and we are currently seeing in the plots from PRs. For example, here is a recently generated plot where it shows two similar cases: ('Fast' has larger computation time than 'Slow')

(and I cross checked, I did not mix the labels; code for quick reference)

[Anirban166]

it seems like this is taking too long and you are not making much progress, so maybe try to focus your time on other low hanging fruit? (other tasks which would be easier/faster to get useful results)

Sure

[tdhock]

here is a recently generated plot where it shows two similar cases: ('Fast' has larger computation time than 'Slow')

actually, in that figure, Fast has smaller computation time, for the setDT test (left). Were you mistaken? Please clarify.

[Anirban166]

You're right, now that I see it again, it makes sense - I wasn't looking at the points or the trend curves, my bad! (I got confused by the labels being above)