Skip to content

Inference timing: add a backtrace to head node#38123

Merged
timholy merged 2 commits into
masterfrom
teh/time_inf_backtrace
Oct 24, 2020
Merged

Inference timing: add a backtrace to head node#38123
timholy merged 2 commits into
masterfrom
teh/time_inf_backtrace

Conversation

@timholy

@timholy timholy commented Oct 21, 2020

Copy link
Copy Markdown
Member

This allows one to identify the caller of runtime-dispatched methods.
This can help detect inference problems and know where to fix them.

Only "head" nodes (entries into type inference) have backtraces.
We avoid doing any processing of the backtrace here, as instruction-pointer
lookup is extremely expensive and we don't even know if the information
will be used.

CC @NHDaly, xref discussion in JuliaDebug/SnoopCompile.jl#139.

Also worth noting that I made a couple of other "cleanups". @NHDaly, two worth noting:

  • I removed some @inline statements, as I have a hard time believing they would have helped. Did you actually test whether they lowered the overhead? I be surprised if calling these methods even registers compared to the cost of inference.
  • I converted some inner constructors to outer. OK? Or did you have efficiency concerns?

This allows one to identify the caller of runtime-dispatched methods.
This can help detect inference problems and know where to fix them.

Only "head" nodes (entries into type inference) have backtraces.
We avoid doing any processing of the backtrace here, as instruction-pointer
lookup is extremely expensive and we don't even know if the information
will be used.

@Sacha0 Sacha0 left a comment

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.

Regarding

- I removed some @inline statements, as I have a hard time believing they would have helped. Did you actually test whether they lowered the overhead? I be surprised if calling these methods even registers compared to the cost of inference.
- I converted some inner constructors to outer. OK? Or did you have efficiency concerns?

Ultimately efficiency became less of a concern than accuracy: Any overhead preceding stop_time = Timings._time_ns() calls and following start = Timings._time_ns() calls gets rolled into the exclusive inference timings, reducing accuracy. Though I can no longer separately recall the impact of each of the changes we made for the sake of accuracy, we did time the impact of those changes, yes, and they were significant. Whether after other changes these changes specifically were significant, I do not know, but we might want to test that their removal doesn't meaningfully impact the accuracy of short exclusive inference timings :).

@timholy

timholy commented Oct 22, 2020

Copy link
Copy Markdown
Member Author

Can you point to some discussion about optimizing it? I don't see anything like that in your comments in #37749, but perhaps this discussion occurred elsewhere.

Regarding the two points I raised above:

  • For the @inline, a function call is typically ~20 CPU cycles, maybe 7ns, and inference of even the simplest methods is tens of microseconds. That's 3 orders of magnitude, so I have a hard time believing that this is an important optimization. Moreover, our optimizer is specifically designed to compare the cost of making the function call vs. the cost of the function itself, so generally I prefer to trust it and only force it to inline in cases where there is reason to believe it might do the wrong thing. Unnecessary inlining increases compile times, which isn't an issue here (very few callers), but still.
  • Looking it over again, the original inner constructors didn't actually avoid allocation of the array (it provided default values rather than leaving things #undef), so this version is really the same (but more Revise-friendly, since you can't Revise inner constructors).

Bottom line, I suspect the two things I highlighted can't really be problems. But I'm happy to put this through its paces if you can point me to the kinds of precision tests you conducted.

@Sacha0

Sacha0 commented Oct 22, 2020

Copy link
Copy Markdown
Member

Can you point to some discussion about optimizing it? I don't see anything like that in your comments in #37749, but perhaps this discussion occurred elsewhere.

Yes, that investigation and discussion occurred offline :).

Bottom line, I suspect the two things I highlighted can't really be problems.

Yes, I agree. I'm merely advocating for verification of that assumption out of an abundance of caution :).

@timholy

timholy commented Oct 22, 2020

Copy link
Copy Markdown
Member Author

I'm merely advocating for verification of that assumption out of an abundance of caution :).

I'm all in favor, but I don't want to reinvent the wheel. Perhaps you and/or @NHDaly can browse through your repl_history.jl and see if you can find out what you did to test it?

@NHDaly NHDaly left a comment

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.

👍 Cool, thanks @timholy! Good idea! :)

Yeah, this LGTM. I'm glad you and @Sacha0 discussed the @inline. In general, I agree with your position on inlining when it comes to performance: trust the compiler on these tradeoffs.
In this specific case though, I'll echo @Sacha0 that we weren't optimizing for efficiency, rather we were optimizing for achieving absolutely as close to 0 instructions as possible in between time_ns() and the call to _typeinf(interp, frame), and between time_ns() and returning.

This is because if the measurement mechanism itself adds overhead to the exclusive time reported of a parent function, then a function that calls many children will have a disproportionately large exclusive time.

I don't care about the whole thing being fast, I just care about it being accurate and precise in terms of attributing time between nodes.

So the way we were measuring this was just by looking at code_native and code_llvm and literally counting instructions in between time_ns() and the next call.

So to achieve that, it seems important that these are inlined. I know that function calls are super fast, but inference is also pretty fast, and if a single function made, say 1000 calls to children, i wouldn't want those 2000 extra function calls to bias its exclusive time.

Does that make sense?

Either way, we should definitely have commented this better, i agree.

Comment thread base/compiler/typeinfer.jl
@timholy

timholy commented Oct 24, 2020

Copy link
Copy Markdown
Member Author

Thanks to both for the review! I restored the forced-inlining. An alternative approach would be to pass the time as an optional argument:

function foo(t = _time_ns())
    # some long body using t
end

will be lowered to the equivalent of

function foo(t)
    # some long body using t
end
foo() = foo(_time_ns())    # this is so small it will be automatically inlined

but I didn't want to change the API for a minor issue like this.

@timholy
timholy merged commit d474c98 into master Oct 24, 2020
@timholy
timholy deleted the teh/time_inf_backtrace branch October 24, 2020 16:33
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.

3 participants