Skip to content

streamline loop in GForce j optimization#3777

Merged
mattdowle merged 6 commits intomasterfrom
gforce_big_j
Aug 29, 2019
Merged

streamline loop in GForce j optimization#3777
mattdowle merged 6 commits intomasterfrom
gforce_big_j

Conversation

@MichaelChirico
Copy link
Copy Markdown
Member

@MichaelChirico MichaelChirico commented Aug 19, 2019

Closes #1470

I guess the original intent of using a for loop was that if nothing in jsub has to be overwritten, no need to copy it. But #1470 is a case where actually nothing is changed, and still copying the whole thing is faster by a factor of 50x

@codecov
Copy link
Copy Markdown

codecov bot commented Aug 19, 2019

Codecov Report

Merging #3777 into master will increase coverage by <.01%.
The diff coverage is 100%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #3777      +/-   ##
==========================================
+ Coverage   99.41%   99.41%   +<.01%     
==========================================
  Files          71       71              
  Lines       13241    13242       +1     
==========================================
+ Hits        13164    13165       +1     
  Misses         77       77
Impacted Files Coverage Δ
R/data.table.R 100% <100%> (ø) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 4ee9264...ebb611a. Read the comment docs.

if (jsub[[1L]]=="list") {
for (ii in seq_along(jsub)[-1L]) {
this_jsub = jsub[[ii]]
if (dotN(this_jsub)) next; # For #5760
Copy link
Copy Markdown
Member Author

@MichaelChirico MichaelChirico Aug 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this dotN thing isn't doing anything? since this loop only affects is.call elements & dotN specifically checks is.name. So is.call and && will accomplish the same.

Copy link
Copy Markdown
Member

@mattdowle mattdowle Aug 28, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1. And all the time was being spent in dotN too. The slowdown wasn't to do with the .optmean part, per se. Rprof output here: #1470 (comment)

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch! Maybe we should revert to the for loop approach then as well (though timings are pretty small in both cases)?

Copy link
Copy Markdown
Member

@mattdowle mattdowle Aug 28, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep good thought. I tried to revert to the for() loop approach but it was still 15s. Down from 30s but not 0.5s as it should be. So now I'm not not sure what's going on. Let's keep the sapply way then and revisit in the future.
Actually, this is consistent with the Rprof result. If I read it correctly, 50% was in the dotN, not "all" as I wrote above.

@mattdowle mattdowle changed the title Closes #1470 -- streamline loop in GForce j optimization streamline loop in GForce j optimization Aug 28, 2019
@mattdowle mattdowle added this to the 1.12.4 milestone Aug 28, 2019
cat("lapply optimization is on, j unchanged as '",deparse(jsub,width.cutoff=200L, nlines=1L),"'\n",sep="")
}
dotN = function(x) is.name(x) && x == ".N" # For #5760
dotN = function(x) is.name(x) && x==".N" # For #5760. TODO: Rprof() showed dotN() may be the culprit if iterated (#1470)?; avoid the == which converts each x to character?
Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

x == quote(.N) works, is it any faster?

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

trying ...

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess not somewhat surprisingly (?):

> microbenchmark::microbenchmark(times = 1e5,
+                                quote(N) == quote(N),
+                                quote(N) == 'N')
Unit: nanoseconds
                 expr min  lq     mean median  uq     max neval
 quote(N) == quote(N) 190 226 309.0476    234 244 3892045 1e+05
      quote(N) == "N" 153 182 213.9202    192 198   39180 1e+05

Ditto if we store qN = quote(N) beforehand for the RHS. identical much worse.

R/data.table.R Outdated
if (jsub[[1L]]=="list") {
GForce = TRUE
for (ii in seq_along(jsub)[-1L]) if (!.ok(jsub[[ii]])) GForce = FALSE
for (ii in seq_along(jsub)[-1L]) if (!.ok(jsub[[ii]])) {GForce = FALSE; break}
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This change is the (good) culprit for the timing strangeness. I've been going back to master and making tweaks there to compare timings to this branch. But this .ok() also calls dotN() hence the confusion. Getting there ...

@mattdowle
Copy link
Copy Markdown
Member

mattdowle commented Aug 28, 2019

50% of the 30s does seem to be the for loop. I whittled it down to the following :

for (ii in seq_along(jsub)) {   # 0.5s  (for the rest of [.data.table, not this loop)
  # this_jsub = jsub[[ii]]
}

for (ii in seq_along(jsub)) {   # 15s  (an extra 14.5s for this loop)
  this_jsub = jsub[[ii]]
}

The Rprof() output for the 15s timing doesn't help much.

> Rprof()
> system.time(DT[,.SD,by=st])
   user  system elapsed 
 13.028   1.052  13.933 
> Rprof(NULL)
> summaryRprof()
$by.self
               self.time self.pct total.time total.pct
"[.data.table"     13.98    98.73      14.08     99.44
"gc"                0.08     0.56       0.08      0.56
"list"              0.06     0.42       0.06      0.42
"FUN"               0.02     0.14       0.02      0.14
"new.env"           0.02     0.14       0.02      0.14

$by.total
                       total.time total.pct self.time self.pct
"system.time"               14.16    100.00      0.00     0.00
"[.data.table"              14.08     99.44     13.98    98.73
"["                         14.08     99.44      0.00     0.00
"gc"                         0.08      0.56      0.08     0.56
"list"                       0.06      0.42      0.06     0.42
"FUN"                        0.02      0.14      0.02     0.14
"new.env"                    0.02      0.14      0.02     0.14
".unsafe.opt"                0.02      0.14      0.00     0.00
"cmp"                        0.02      0.14      0.00     0.00
"cmpCall"                    0.02      0.14      0.00     0.00
"cmpfun"                     0.02      0.14      0.00     0.00
"compiler:::tryCmpfun"       0.02      0.14      0.00     0.00
"doTryCatch"                 0.02      0.14      0.00     0.00
"findCenvVar"                0.02      0.14      0.00     0.00
"genCode"                    0.02      0.14      0.00     0.00
"getInlineInfo"              0.02      0.14      0.00     0.00
"h"                          0.02      0.14      0.00     0.00
"lapply"                     0.02      0.14      0.00     0.00
"tryCatch"                   0.02      0.14      0.00     0.00
"tryCatchList"               0.02      0.14      0.00     0.00
"tryCatchOne"                0.02      0.14      0.00     0.00
"tryInline"                  0.02      0.14      0.00     0.00

There isn't even any subassign to the jsub here. So I'm not sure what's going on. Next step would be to attempt to reproduce independently of data.table and then ask on r-devel. A long dummy jsub could be created to do that in a fresh vanilla R session.

Since the PR is working great by doing away with the for loop, I'll merge and move on.

@mattdowle mattdowle merged commit f10402c into master Aug 29, 2019
@mattdowle mattdowle deleted the gforce_big_j branch August 29, 2019 00:07
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Bug report - RSession Hangs

3 participants