Attribution of Timings on Non Logged Calls

[brodieG]

Ran into issues with calls to [ that were real slow but made it seem like something else was slow.

[brodieG]

Possibly related:

> treeprof::treeprof(as.factor(grp))
Profiling
auto gc: running with gc() first
First run in 1.814 seconds
Looping to 5 seconds
Parsing Rprof
Done
Ticks: 756; Iterations: 3; Time Per: 1.668 seconds; Time Total: 5.004 seconds; Time Ticks: 0.756

                           milliseconds
as.factor --------------- : 1668 -    0
    sort ---------------- : 1661 -    0
        unique.default -- : 1580 - 1580
        sort.default ---- :   82 -    0
            sort.int ---- :   82 -   26
                order --- :   55 -   55
> str(grp)
 int [1:10000000] 672260 429338 810261 630278 885076 809421 467163 185561 291758 398233 ...
> Rprof()
> zz <- as.factor(grp)
> Rprof(NULL)
> summaryRprof()
$by.self
                 self.time self.pct total.time total.pct
"unique.default"      0.88    53.66       0.88     53.66
"as.factor"           0.74    45.12       1.64    100.00
"order"               0.02     1.22       0.02      1.22

$by.total
                 total.time total.pct self.time self.pct
"as.factor"            1.64    100.00      0.74    45.12
"sort"                 0.90     54.88      0.00     0.00
"unique.default"       0.88     53.66      0.88    53.66
"order"                0.02      1.22      0.02     1.22
"sort.default"         0.02      1.22      0.00     0.00
"sort.int"             0.02      1.22      0.00     0.00

$sample.interval
[1] 0.02

$sampling.time
[1] 1.64

> as.factor
function (x) 
{
    if (is.factor(x)) 
        x
    else if (!is.object(x) && is.integer(x)) {
        levels <- sort(unique.default(x))
        f <- match(x, levels)
        levels(f) <- as.character(levels)
        if (!is.null(nx <- names(x))) 
            names(f) <- nx
        class(f) <- "factor"
        f
    }
    else factor(x)
}
<bytecode: 0x7ffbe2a501f8>
<environment: namespace:base>

Basically, the match call should be getting attributed to as.factor, but instead it is getting attributed to the preceding unique.default call:

sample.interval=20000
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"unique.default" "sort" "as.factor" 
"order" "sort.int" "sort.default" "sort" "as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 
"as.factor" 

Not sure if related. It maybe that the top level call is just dropped, and then all the timing is allocated to what remains. This supports it:

> f <- function(x) as.factor(x)
> treeprof::treeprof(f(grp))
Profiling
auto gc: running with gc() first
First run in 1.776 seconds
Looping to 5 seconds
Parsing Rprof
Done
Ticks: 1518; Iterations: 3; Time Per: 1.605 seconds; Time Total: 4.816 seconds; Time Ticks: 1.518

                              milliseconds
f --------------------------- : 1605 -   0
    as.factor --------------- : 1605 - 752
        sort ---------------- :  850 -   0
            unique.default -- :  802 - 802
            sort.default ---- :   49 -   0
                sort.int ---- :   49 -   3
                    order --- :   45 -  45