ODIn
/
spark-instrumented-optimizer
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

added logging for expression transformations.

macrotesting
Nick Brown 2022-07-12 13:35:14 -04:00
parent 73cb9049e6
commit 9b6beb068b
Signed by: bicknrown
GPG Key ID: 47AF495B3DCCE9C3
3 changed files with 57 additions and 14 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

11
plotting/plotting.py
View File

@ -73,6 +73,7 @@ for root, dirs, files in os.walk(dataOutputDirectory):
# manipulating data
xAxis = []
search = []
transformExpression = []
ineffective = []
effective = []
execution = []
@ -83,6 +84,7 @@ for rootKey in queryDataDict:
for i in range(1,23):
xAxis.append(("Q" + str(i)))
search.append(queryDataDict[str(i)]["transformTime"] / 1000000000.0)
transformExpression.append(queryDataDict[str(i)]["transformExpressionTime"] / 1000000000.0)
ineffective.append(queryDataDict[str(i)]["ineffectiveMatchTime"] /1000000000.0)
effective.append(queryDataDict[str(i)]["effectiveMatchTime"] / 1000000000.0)
execution.append(queryDataDict[str(i)]["executorTime"] / 1000000000.0)
@ -97,10 +99,11 @@ plt.ylim(ymin = 0, ymax = 3)
plt.xlabel('TPC-H Query #')
plt.ylabel('Total Time Spent Optimizing (sec)')
plt.bar(xAxis, search, label='Search', color = '#00263E')
plt.bar(xAxis, ineffective, label='Ineffective Rewrites', color = '#0062A0', bottom = search)
plt.bar(xAxis, effective, label='Effective Rewrites', color = '#409EDA', bottom = np.array(search) + np.array(ineffective))
plt.bar(xAxis, execution, label='Fixpoint Loop', color = '#76C8FC', bottom = np.array(search) + np.array(ineffective) + np.array(effective))
plt.bar(xAxis, leftover, label='Untracked', color = '#7A0097', bottom = np.array(search) + np.array(ineffective) + np.array(effective) + np.array(execution))
plt.bar(xAxis, transformExpression, label='Expression Transformations', color = '#B09ABA', bottom = search)
plt.bar(xAxis, ineffective, label='Ineffective Rewrites', color = '#0062A0', bottom = np.array(search) + np.array(transformExpression))
plt.bar(xAxis, effective, label='Effective Rewrites', color = '#409EDA', bottom = np.array(search) + np.array(transformExpression) + np.array(ineffective))
plt.bar(xAxis, execution, label='Fixpoint Loop', color = '#76C8FC', bottom = np.array(search) + np.array(transformExpression) + np.array(ineffective) + np.array(effective))
plt.bar(xAxis, leftover, label='Untracked', color = '#7A0097', bottom = np.array(search) + np.array(transformExpression) + np.array(ineffective) + np.array(effective) + np.array(execution))
plt.legend(loc="upper left")
plt.savefig(graphOutputDirectory + stackedGraphOutputFile ,bbox_inches='tight')

54
sql/catalyst/src/main/scala/org/apache/spark/sql/catalyst/CustomLogger.scala
View File

@ -20,6 +20,10 @@ package org.apache.spark.sql.catalyst
import scala.collection.mutable.Map
import scala.collection.mutable.Set
import scala.collection.mutable.Stack
import scala.reflect.runtime.universe._
import org.apache.spark.sql.catalyst.expressions.Expression
import org.apache.spark.sql.catalyst.plans.logical.LogicalPlan
object CustomLogger
{
@ -28,6 +32,7 @@ object CustomLogger
val applyString: String = "Apply"
val transformString: String = "Transform"
val transformExpressionString: String = "TransformExpression"
val matchString: String = "Match"
val potentialMatchString: String = "Potential Match"
val effectiveMatchString: String = "Effective Match"
@ -37,6 +42,7 @@ object CustomLogger
val stateTimes: Map[String, Long] = Map[String, Long](
applyString -> 0,
transformString -> 0,
transformExpressionString -> 0,
matchString -> 0,
effectiveMatchString -> 0,
potentialMatchString -> 0,
@ -44,6 +50,7 @@ object CustomLogger
executorString -> 0
)
var transformExpressionLogState: Boolean = false
var tempMatchBucket: Long = 0;
val intermediateStateStack: Stack[String] = Stack[String]()
var previousTimeStamp: Long = 0
@ -168,9 +175,9 @@ object CustomLogger
// scalastyle:on println
)(anonFunc: => F): F =
{
push("Apply")
push(applyString)
val anonFuncRet = anonFunc
pop("Apply")
pop(applyString)
anonFuncRet
}
@ -183,12 +190,37 @@ object CustomLogger
// scalastyle:on println
)(anonFunc: => F): F =
{
push("Transform")
transformExpressionLogState = true
push(transformString)
val anonFuncRet = anonFunc
pop("Transform")
pop(transformString)
transformExpressionLogState = false
anonFuncRet
}
def logTransformExpressionTime[F](
descriptor: String = "",
context: String = "",
log: (String => Unit) =
// scalastyle:off println
println(_)
// scalastyle:on println
)(anonFunc: => F): F =
{
if (transformExpressionLogState)
{
push(transformExpressionString)
val anonFuncRet = anonFunc
pop(transformExpressionString)
anonFuncRet
}
else
{
val anonFuncRet = anonFunc
anonFuncRet
}
}
def logMatchTime[F](
descriptor: String = "",
unAffected: Boolean = false,
@ -199,9 +231,9 @@ object CustomLogger
// scalastyle:on println
)(anonFunc: => F): F =
{
push("Match")
push(matchString)
val anonFuncRet = anonFunc
pop("Match")
pop(matchString)
anonFuncRet
}
@ -214,9 +246,9 @@ object CustomLogger
// scalastyle:on
)(anonFunc: => F): F =
{
push("Executor")
push(executorString)
val anonFuncRet = anonFunc
pop("Executor")
pop(executorString)
anonFuncRet
}
@ -232,6 +264,7 @@ object CustomLogger
{
val applyTime: Long = stateTimes.getOrElse(applyString, -27)
val transformTime: Long = stateTimes.getOrElse(transformString, -27)
val transformExpressionTime: Long = stateTimes.getOrElse(transformExpressionString, -27)
val matchTime: Long = stateTimes.getOrElse(matchString, -27)
val effectiveMatchTime: Long = stateTimes.getOrElse(effectiveMatchString, -27)
val ineffectiveMatchTime: Long = stateTimes.getOrElse(ineffectiveMatchString, -27)
@ -242,7 +275,7 @@ object CustomLogger
// scalastyle:off
print(s"""
------------------------------
{"data":{"applyTime": $applyTime, "transformTime": $transformTime, "matchTime": $matchTime, "effectiveMatchTime": $effectiveMatchTime, "ineffectiveMatchTime": $ineffectiveMatchTime, "executorTime": $executorTime}}
{"data":{"applyTime": $applyTime, "transformTime": $transformTime, "transformExpressionTime": $transformExpressionTime, "matchTime": $matchTime, "effectiveMatchTime": $effectiveMatchTime, "ineffectiveMatchTime": $ineffectiveMatchTime, "executorTime": $executorTime}}
------------------------------
""")
// scalastyle:on
@ -252,6 +285,7 @@ object CustomLogger
{
val applyTimeSec: Double = (applyTime / 1000000000.0)
val transformTimeSec: Double = (transformTime / 1000000000.0)
val transformExpressionTimeSec: Double = (transformExpressionTime / 1000000000.0)
val effectiveMatchTimeSec: Double = (effectiveMatchTime / 1000000000.0)
val ineffectiveMatchTimeSec: Double = (ineffectiveMatchTime / 1000000000.0)
val matchTimeSec: Double = (matchTime / 1000000000.0)
@ -272,6 +306,8 @@ Total time for applying rules: $applyTime ns or $applyTimeSec seconds.
Total time for searching: $transformTime ns or $transformTimeSec seconds.
Total time for expression transformations: $transformExpressionTime ns or $transformExpressionTimeSec seconds.
Time for effective rule matching: $effectiveMatchTime ns or $effectiveMatchTimeSec seconds.

6
sql/catalyst/src/main/scala/org/apache/spark/sql/catalyst/plans/QueryPlan.scala
View File

@ -20,6 +20,7 @@ package org.apache.spark.sql.catalyst.plans
import scala.collection.mutable
import org.apache.spark.sql.AnalysisException
import org.apache.spark.sql.catalyst.CustomLogger
import org.apache.spark.sql.catalyst.SQLConfHelper
import org.apache.spark.sql.catalyst.expressions._
import org.apache.spark.sql.catalyst.rules.RuleId
@ -120,7 +121,10 @@ abstract class QueryPlan[PlanType <: QueryPlan[PlanType]]
def transformExpressionsWithPruning(cond: TreePatternBits => Boolean,
ruleId: RuleId = UnknownRuleId)(rule: PartialFunction[Expression, Expression])
: this.type = {
transformExpressionsDownWithPruning(cond, ruleId)(rule)
CustomLogger.logTransformExpressionTime()
{
transformExpressionsDownWithPruning(cond, ruleId)(rule)
}
}
/**