[query] Use sourcecode.Enclosing to handle timed blocks implicitly

[ehigham]

Change Description

This change exists as part of larger refactoring work. Herein, I've exchanged
hard-coded contextual strings passed to ExecutionTimer.time with implict
contexts, drawing inspiration from scalatest.

These contexts are now supplied after entering functions like Compile and
Emit instead of before (see ExecuteContext.time). By sprinking calls to
time throughout the codebase after entering functions, we obtain a nice trace
of the timings with sourcecode.Enclosing, minus the previous verbosity.

See [1] for more information about what pre-built macros are available. We can
always build our own later. See comments in [pull request id] for example output.
Note that ExectionTimer.time still accepts a string to support uses like
Optimise and LoweringPass where those contexts are provided already.
It is also exception-safe now.

This change exposed many similarities between the implementations of query
execution across all three backends. I've stopped short of full unification
which is a greater work, I've instead simplified and moved duplicated result
encoding into the various backend api implementations.

More interesting changes are to ExecuteContext, which now supports

• time, as discussed above
• local, a generalisation for temporarily overriding properties of an
  ExecuteContext (inspired by [2]). While I've long wanted this for testing,
  we were doing some questionable things when reporting timings back to python,
  for which locally overriding the timer of a ctx has been very useful.
  We also follow this pattern for local regions

[1] https://github.com/com-lihaoyi/sourcecode
[2] https://hackage.haskell.org/package/mtl-2.3.1/docs/Control-Monad-Reader.html#v:local

Security Assessment

This change has no security impact as it's confined to refactoring of existing non-security-related code.

[ehigham]

• [query] Unify CloudCredentials and Simplify BatchClient #14684 : 2 dependent PRs (#14686 , #14747 )
• [query] Use sourcecode.Enclosing to handle timed blocks implicitly #14683 👈 (View in Graphite)
• main

This stack of pull requests is managed by Graphite. Learn more about stacking.

[chrisvittal]

Here's what I noticed in my first pass. I think it's probably, pretty good otherwise.

[chrisvittal]

I'm satisfied. Helps clean things up a bunch. Thanks!

[ehigham]

• [query] unify backend rpc #14693
• [query] Remove persistedIr from Backend interface #14692
• [query] Remove lookupOrCompileCachedFunction from Backend interface #14691
• [query] Remove BlockMatrix persist from Backend interface #14690
• [query] Expose references via ExecuteContext #14686
• [query] Unify CloudCredentials and Simplify BatchClient #14684
• [query] Use sourcecode.Enclosing to handle timed blocks implicitly #14683 👈
• main

This stack of pull requests is managed by Graphite. Learn more about stacking.

Join @ehigham and the rest of your teammates on Graphite

[ehigham]

• [query] unify backend rpc #14693
• [query] Remove persistedIr from Backend interface #14692
• [query] Remove lookupOrCompileCachedFunction from Backend interface #14691
• [query] Remove BlockMatrix persist from Backend interface #14690
• [query] Expose references via ExecuteContext #14686
• [query] Unify CloudCredentials and Simplify BatchClient #14684
• [query] Use sourcecode.Enclosing to handle timed blocks implicitly #14683 👈
• main

This stack of pull requests is managed by Graphite. Learn more about stacking.

Join @ehigham and the rest of your teammates on Graphite

[patrick-schultz]

This is a really great change! I have a few small comments/requests, but overall I'm excited to get this merged!

[ehigham]

Example timing output:

timing is.hail.backend.BackendHttpHandler#handle x$3 total 1.426s self 157.884ms children 1.268s %children 88.93%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.expr.ir.TypeCheck.apply total 23.246ms self 23.246ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute total 1.245s self 3.019ms children 1.242s %children 99.76%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.TypeCheck.apply total 0.327ms self 0.327ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.analyses.SemanticHash.apply total 29.792ms self 6.254ms children 23.538ms %children 79.01%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.analyses.SemanticHash.apply/is.hail.expr.ir.NormalizeNames.apply total 23.538ms self 23.538ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.backend.spark.SparkBackend#_jvmLowerAndExecute total 0.053ms self 0.053ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply total 1.211s self 27.866ms children 1.183s %children 97.70%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR total 37.247ms self 0.358ms children 36.889ms %children 99.04%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Verify total 0.268ms self 0.268ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform total 36.599ms self 2.385ms children 34.214ms %children 93.48%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/FoldConstants, iteration: 0 total 4.078ms self 4.078ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/ExtractIntervalFilters, iteration: 0 total 0.898ms self 0.898ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/NormalizeNames, iteration: 0 total 2.553ms self 0.011ms children 2.543ms %children 99.59%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/NormalizeNames, iteration: 0/is.hail.expr.ir.NormalizeNames.apply total 2.543ms self 2.543ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/Simplify, iteration: 0 total 8.675ms self 8.675ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/ForwardLets, iteration: 0 total 4.506ms self 3.993ms children 0.513ms %children 11.40%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/ForwardLets, iteration: 0/is.hail.expr.ir.NormalizeNames.apply total 0.513ms self 0.513ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/is.hail.expr.ir.TypeCheck.apply total 0.120ms self 0.120ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/ForwardRelationalLets, iteration: 0 total 0.796ms self 0.796ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/is.hail.expr.ir.TypeCheck.apply total 0.111ms self 0.111ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/PruneDeadFields, iteration: 0 total 9.943ms self 9.943ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/FoldConstants, iteration: 1 total 0.414ms self 0.414ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/ExtractIntervalFilters, iteration: 1 total 0.021ms self 0.021ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/NormalizeNames, iteration: 1 total 0.384ms self 0.005ms children 0.379ms %children 98.72%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/NormalizeNames, iteration: 1/is.hail.expr.ir.NormalizeNames.apply total 0.379ms self 0.379ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/Simplify, iteration: 1 total 0.103ms self 0.103ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/ForwardLets, iteration: 1 total 0.579ms self 0.273ms children 0.306ms %children 52.84%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/ForwardLets, iteration: 1/is.hail.expr.ir.NormalizeNames.apply total 0.306ms self 0.306ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/is.hail.expr.ir.TypeCheck.apply total 0.143ms self 0.143ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/ForwardRelationalLets, iteration: 1 total 0.025ms self 0.025ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/is.hail.expr.ir.TypeCheck.apply total 0.151ms self 0.151ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Transform/PruneDeadFields, iteration: 1 total 0.714ms self 0.714ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, initial IR/Verify total 0.022ms self 0.022ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/is.hail.expr.ir.TypeCheck.apply total 0.124ms self 0.124ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/LowerMatrixToTable total 4.039ms self 0.016ms children 4.023ms %children 99.60%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/LowerMatrixToTable/Verify total 0.012ms self 0.012ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/LowerMatrixToTable/Transform total 3.992ms self 3.992ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/LowerMatrixToTable/Verify total 0.019ms self 0.019ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/is.hail.expr.ir.TypeCheck.apply total 0.132ms self 0.132ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable total 2.591ms self 0.010ms children 2.581ms %children 99.63%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Verify total 0.011ms self 0.011ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform total 2.548ms self 0.302ms children 2.246ms %children 88.15%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/FoldConstants, iteration: 0 total 0.307ms self 0.307ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/ExtractIntervalFilters, iteration: 0 total 0.016ms self 0.016ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/NormalizeNames, iteration: 0 total 0.363ms self 0.004ms children 0.358ms %children 98.82%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/NormalizeNames, iteration: 0/is.hail.expr.ir.NormalizeNames.apply total 0.358ms self 0.358ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/Simplify, iteration: 0 total 0.077ms self 0.077ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/ForwardLets, iteration: 0 total 0.659ms self 0.292ms children 0.367ms %children 55.66%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/ForwardLets, iteration: 0/is.hail.expr.ir.NormalizeNames.apply total 0.367ms self 0.367ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/is.hail.expr.ir.TypeCheck.apply total 0.127ms self 0.127ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/ForwardRelationalLets, iteration: 0 total 0.030ms self 0.030ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/is.hail.expr.ir.TypeCheck.apply total 0.095ms self 0.095ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Transform/PruneDeadFields, iteration: 0 total 0.572ms self 0.572ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/Optimize: relationalLowerer, after LowerMatrixToTable/Verify total 0.022ms self 0.022ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/is.hail.expr.ir.TypeCheck.apply total 0.144ms self 0.144ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/LiftRelationalValuesToRelationalLets total 1.135ms self 0.009ms children 1.126ms %children 99.21%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/LiftRelationalValuesToRelationalLets/Verify total 0.027ms self 0.027ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/LiftRelationalValuesToRelationalLets/Transform total 1.069ms self 1.069ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/LiftRelationalValuesToRelationalLets/Verify total 0.029ms self 0.029ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/is.hail.expr.ir.TypeCheck.apply total 0.233ms self 0.233ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/EvalRelationalLets total 1.101s self 0.007ms children 1.101s %children 100.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/EvalRelationalLets/Verify total 0.023ms self 0.023ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/EvalRelationalLets/Transform total 1.101s self 2.119ms children 1.098s %children 99.81%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/EvalRelationalLets/Transform/LowerAndExecuteShuffles total 1.549ms self 0.008ms children 1.541ms %children 99.47%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/EvalRelationalLets/Transform/LowerAndExecuteShuffles/Verify total 0.016ms self 0.016ms children 0.000ms %children 0.00%
timing is.hail.backend.BackendHttpHandler#handle x$3/is.hail.backend.spark.SparkBackend#execute/is.hail.expr.ir.CompileAndEvaluate._apply/EvalRelationalLets/Transform/LowerAndExecuteShuffles/Transform total 1.506ms self 1.506ms children 0.000ms %children 0.00%

[patrick-schultz]

Responded in threads

[patrick-schultz]

Thanks again for the great change, and sorry for the slow review!