[SPARK-31315][SQL] SQLQueryTestSuite: Display the total compile time for generated java code #28081

beliefer · 2020-03-31T11:36:49Z

What changes were proposed in this pull request?

After my investigation, SQLQueryTestSuite spent a lot of time compiling the generated java code.
Take group-by.sql as an example.
At first, I added some debug log into SQLQueryTestSuite.
Please reference https://github.com/beliefer/spark/blob/92b6af740c73e33007c21592023eb65635bb0f07/sql/core/src/test/scala/org/apache/spark/sql/SQLQueryTestSuite.scala#L402
The execution command is as follows:
build/sbt "~sql/test-only *SQLQueryTestSuite -- -z group-by.sql"
The output show below:

00:56:06.192 WARN org.apache.spark.sql.SQLQueryTestSuite: group-by.sql using configs: spark.sql.codegen.wholeStage=true. run time: 20604
00:56:13.719 WARN org.apache.spark.sql.SQLQueryTestSuite: group-by.sql using configs: spark.sql.codegen.wholeStage=false,spark.sql.codegen.factoryMode=CODEGEN_ONLY. run time: 7526
00:56:18.786 WARN org.apache.spark.sql.SQLQueryTestSuite: group-by.sql using configs: spark.sql.codegen.wholeStage=false,spark.sql.codegen.factoryMode=NO_CODEGEN. run time: 5066

According to the log, we know.

Config	Run time(ms)
spark.sql.codegen.wholeStage=true	20604
spark.sql.codegen.wholeStage=false,spark.sql.codegen.factoryMode=CODEGEN_ONLY	7526
spark.sql.codegen.wholeStage=false,spark.sql.codegen.factoryMode=NO_CODEGEN	5066

We should display the total compile time for generated java code.

This PR will add the following to SQLQueryTestSuite's output.

=== Metrics of Whole Codegen ===
Total compile time: 80.564516529 seconds

Note: At first, I wanted to use CodegenMetrics.METRIC_COMPILATION_TIME to do this. After many experiments, I found that CodegenMetrics.METRIC_COMPILATION_TIME is only effective for a single test case, and cannot play a role in the whole life cycle of SQLQueryTestSuite.
I checked the type of CodegenMetrics.METRIC_COMPILATION_TIME is Histogram and the latter preserves 1028 elements. Histogram is a metric which calculates the distribution of a value.

Why are the changes needed?

Display the total compile time for generated java code.

Does this PR introduce any user-facing change?

'No'.

How was this patch tested?

Jenkins test.

SparkQA · 2020-03-31T16:21:24Z

Test build #120643 has finished for PR 28081 at commit 41aa7e9.

This patch passes all tests.
This patch merges cleanly.
This patch adds no public classes.

maropu · 2020-04-01T01:26:02Z

sql/core/src/test/scala/org/apache/spark/sql/SQLQueryTestSuite.scala

+      val codegenInfo =
+        s"""
+           |=== Metrics of Whole Codegen ===
+           |Total compile time: ${CodeGenerator.compileTime.sum.toDouble / NANOS_PER_SECOND} seconds


Probably, we need to reset this metric in beforeAll? btw , could we reuse CodegenMetrics.METRIC_COMPILATION_TIME for this purpose? Getting the same metric for the same purpose seems redundant.

At first, I wanted to use CodegenMetrics.METRIC_COMPILATION_TIME to do this. After many experiments, I found that CodegenMetrics.METRIC_COMPILATION_TIME is only effective for a single test case, and cannot play a role in the whole life cycle of SQLQueryTestSuite.
I checked the type of CodegenMetrics.METRIC_COMPILATION_TIME is Histogram that is it only preserves 1028 elements.

@maropu Histogram is a metric which calculates the distribution of a value.

maropu · 2020-04-01T01:26:53Z

Could we display this metric in BenchmarkQueryTest, too?

SparkQA · 2020-04-01T07:51:52Z

Test build #120662 has finished for PR 28081 at commit 3dd0adf.

This patch passes all tests.
This patch merges cleanly.
This patch adds no public classes.

beliefer · 2020-04-01T08:02:05Z

cc @srowen @cloud-fan

beliefer · 2020-04-01T08:13:38Z

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

+          val duration = endTime - startTime
+          val timeMs: Double = duration.toDouble / NANOS_PER_MILLIS
          CodegenMetrics.METRIC_SOURCE_CODE_SIZE.update(code.body.length)
          CodegenMetrics.METRIC_COMPILATION_TIME.update(timeMs.toLong)


CodegenMetrics.METRIC_COMPILATION_TIME is a Histogram that is a metric which calculates the distribution of a value. We can't reuse it.

cloud-fan · 2020-04-01T08:43:56Z

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

          CodegenMetrics.METRIC_SOURCE_CODE_SIZE.update(code.body.length)
          CodegenMetrics.METRIC_COMPILATION_TIME.update(timeMs.toLong)
          logInfo(s"Code generated in $timeMs ms")
+          _compileTime.add(duration)


I think timeMs is good enough to be recorded.

timeMs lost a lot of precision. Because SQLQueryTestSuite contains 231 test cases contain a lot of SQL, tens of thousands of SQL are executed. The loss of accuracy will increase.

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

dongjoon-hyun

When a source code under src/main is changed, [TESTS] should not be used.

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

dongjoon-hyun · 2020-04-01T21:15:38Z

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

+
+  def compileTime: Long = _compileTime.sum
+
+  def resetCompileTime: Unit = _compileTime.reset()


dongjoon-hyun · 2020-04-01T21:19:38Z

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

  // bytecode instruction
  final val MUTABLESTATEARRAY_SIZE_LIMIT = 32768

+  // Display the total compile time for generating java code in the output of the test case.


Although this is designed for a test case, this is a general accumulator in the context of CodeGenerator. Could you revise into a more proper description?
cc @gatorsmile

Also, this doesn't Display anything here. The warning log happens in afterAll in SQLQueryTestSuite.

OK. I will supplement a more proper description.

beliefer · 2020-04-02T01:16:08Z

When a source code under src/main is changed, [TESTS] should not be used.

OK. Thank you. I get it.

beliefer · 2020-04-02T01:55:02Z

Could we display this metric in BenchmarkQueryTest, too?

The run time of BenchmarkQueryTest is smaller. I'm not sure if I should consider it.

SparkQA · 2020-04-02T06:16:55Z

Test build #120704 has finished for PR 28081 at commit 1d7dc2f.

This patch passes all tests.
This patch merges cleanly.
This patch adds no public classes.

cloud-fan · 2020-04-02T06:42:43Z

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

+  private val _compileTime = new LongAccumulator
+
+  // Visible for testing
+  def compileTime: Long = _compileTime.sum


We should mention that it's time in nanoseconds

OK. I will add it.

cloud-fan · 2020-04-02T09:13:19Z

The last commit just adds a line of comment. I'm merging it to master, thanks!

beliefer · 2020-04-02T11:19:34Z

@cloud-fan @maropu @dongjoon-hyun Thanks for all your help!

SparkQA · 2020-04-02T13:19:37Z

Test build #120717 has finished for PR 28081 at commit eb27c3a.

This patch passes all tests.
This patch merges cleanly.
This patch adds no public classes.

rednaxelafx · 2020-04-03T09:24:09Z

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

  // bytecode instruction
  final val MUTABLESTATEARRAY_SIZE_LIMIT = 32768

+  // The java source code generated by whole codegen is compiled on the Driver side and sent to


Hi @beliefer ,

I'm really sorry to post edit suggestions after the PR is merged. I noticed this PR just now...

If we have a chance to make follow-up changes, could you please update java code to Java code, and whole codegen to whole-stage codegen?

Thanks!

OK. Thanks for your remind.

@beliefer can you send a followup PR to address it?

@cloud-fan @rednaxelafx I make a followup PR #28112.

This one? #28112

… for generated java code ### What changes were proposed in this pull request? After my investigation, SQLQueryTestSuite spent a lot of time to generate java code. This PR is related to #28081. #28081 used to display compile time, but this PR used to display generate time. This PR will add the following to `SQLQueryTestSuite`'s output. ``` === Metrics of Whole Codegen === Total generate time: 82.640913862 seconds Total compile time: 98.649663572 seconds ``` ### Why are the changes needed? Display the total generate time for generated java code. ### Does this PR introduce any user-facing change? 'No'. ### How was this patch tested? Jenkins test. Closes #28105 from beliefer/output-codegen-generation-time. Lead-authored-by: beliefer <[email protected]> Co-authored-by: Jiaan Geng <[email protected]> Signed-off-by: Wenchen Fan <[email protected]>

…for generated java code ### What changes were proposed in this pull request? After my investigation, `SQLQueryTestSuite` spent a lot of time compiling the generated java code. Take `group-by.sql` as an example. At first, I added some debug log into `SQLQueryTestSuite`. Please reference https://github.com/beliefer/spark/blob/92b6af740c73e33007c21592023eb65635bb0f07/sql/core/src/test/scala/org/apache/spark/sql/SQLQueryTestSuite.scala#L402 The execution command is as follows: `build/sbt "~sql/test-only *SQLQueryTestSuite -- -z group-by.sql"` The output show below: ``` 00:56:06.192 WARN org.apache.spark.sql.SQLQueryTestSuite: group-by.sql using configs: spark.sql.codegen.wholeStage=true. run time: 20604 00:56:13.719 WARN org.apache.spark.sql.SQLQueryTestSuite: group-by.sql using configs: spark.sql.codegen.wholeStage=false,spark.sql.codegen.factoryMode=CODEGEN_ONLY. run time: 7526 00:56:18.786 WARN org.apache.spark.sql.SQLQueryTestSuite: group-by.sql using configs: spark.sql.codegen.wholeStage=false,spark.sql.codegen.factoryMode=NO_CODEGEN. run time: 5066 ``` According to the log, we know. Config | Run time(ms) -- | -- spark.sql.codegen.wholeStage=true | 20604 spark.sql.codegen.wholeStage=false,spark.sql.codegen.factoryMode=CODEGEN_ONLY | 7526 spark.sql.codegen.wholeStage=false,spark.sql.codegen.factoryMode=NO_CODEGEN | 5066 We should display the total compile time for generated java code. This PR will add the following to `SQLQueryTestSuite`'s output. ``` === Metrics of Whole Codegen === Total compile time: 80.564516529 seconds ``` Note: At first, I wanted to use `CodegenMetrics.METRIC_COMPILATION_TIME` to do this. After many experiments, I found that `CodegenMetrics.METRIC_COMPILATION_TIME` is only effective for a single test case, and cannot play a role in the whole life cycle of `SQLQueryTestSuite`. I checked the type of ` CodegenMetrics.METRIC_COMPILATION_TIME` is `Histogram` and the latter preserves 1028 elements.` Histogram` is a metric which calculates the distribution of a value. ### Why are the changes needed? Display the total compile time for generated java code. ### Does this PR introduce any user-facing change? 'No'. ### How was this patch tested? Jenkins test. Closes apache#28081 from beliefer/output-codegen-compile-time. Lead-authored-by: beliefer <[email protected]> Co-authored-by: gengjiaan <[email protected]> Signed-off-by: Wenchen Fan <[email protected]>

… for generated java code ### What changes were proposed in this pull request? After my investigation, SQLQueryTestSuite spent a lot of time to generate java code. This PR is related to apache#28081. apache#28081 used to display compile time, but this PR used to display generate time. This PR will add the following to `SQLQueryTestSuite`'s output. ``` === Metrics of Whole Codegen === Total generate time: 82.640913862 seconds Total compile time: 98.649663572 seconds ``` ### Why are the changes needed? Display the total generate time for generated java code. ### Does this PR introduce any user-facing change? 'No'. ### How was this patch tested? Jenkins test. Closes apache#28105 from beliefer/output-codegen-generation-time. Lead-authored-by: beliefer <[email protected]> Co-authored-by: Jiaan Geng <[email protected]> Signed-off-by: Wenchen Fan <[email protected]>

gatorsmile · 2020-04-18T06:18:47Z

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala

+
+  // Reset compile time.
+  // Visible for testing
+  def resetCompileTime: Unit = _compileTime.reset()


Methods should be declared with parentheses, unless they are accessors that have no side-effect. See: https://github.com/databricks/scala-style-guide#parentheses

Fixed in #28252

@gatorsmile Thanks. I got it now.

Display compile time.

41aa7e9

maropu reviewed Apr 1, 2020

View reviewed changes

Add reset

3dd0adf

beliefer commented Apr 1, 2020

View reviewed changes

cloud-fan reviewed Apr 1, 2020

View reviewed changes

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala Show resolved Hide resolved

dongjoon-hyun changed the title ~~[SPARK-31315][SQL][TEST] SQLQueryTestSuite: Display the total compile time for generated java code~~ [SPARK-31315][SQL] SQLQueryTestSuite: Display the total compile time for generated java code Apr 1, 2020

dongjoon-hyun reviewed Apr 1, 2020

View reviewed changes

dongjoon-hyun added the SQL label Apr 1, 2020

dongjoon-hyun reviewed Apr 1, 2020

View reviewed changes

...atalyst/src/main/scala/org/apache/spark/sql/catalyst/expressions/codegen/CodeGenerator.scala Show resolved Hide resolved

dongjoon-hyun reviewed Apr 1, 2020

View reviewed changes

Optimize code

1d7dc2f

cloud-fan reviewed Apr 2, 2020

View reviewed changes

cloud-fan approved these changes Apr 2, 2020

View reviewed changes

Add unit of time.

eb27c3a

cloud-fan closed this in a9260d0 Apr 2, 2020

beliefer mentioned this pull request Apr 3, 2020

[SPARK-31316][SQL] SQLQueryTestSuite: Display the total generate time for generated java code. #28105

Closed

rednaxelafx reviewed Apr 3, 2020

View reviewed changes

gatorsmile reviewed Apr 18, 2020

View reviewed changes

beliefer deleted the output-codegen-compile-time branch April 23, 2024 07:11


		def compileTime: Long = _compileTime.sum

		def resetCompileTime: Unit = _compileTime.reset()

[SPARK-31315][SQL] SQLQueryTestSuite: Display the total compile time for generated java code #28081

[SPARK-31315][SQL] SQLQueryTestSuite: Display the total compile time for generated java code #28081

Uh oh!

Conversation

beliefer commented Mar 31, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What changes were proposed in this pull request?

Why are the changes needed?

Does this PR introduce any user-facing change?

How was this patch tested?

Uh oh!

SparkQA commented Mar 31, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

beliefer Apr 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

maropu commented Apr 1, 2020

Uh oh!

SparkQA commented Apr 1, 2020

Uh oh!

beliefer commented Apr 1, 2020

Uh oh!

beliefer Apr 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

dongjoon-hyun left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dongjoon-hyun Apr 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

beliefer commented Apr 2, 2020

Uh oh!

beliefer commented Apr 2, 2020

Uh oh!

SparkQA commented Apr 2, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cloud-fan commented Apr 2, 2020

Uh oh!

beliefer commented Apr 2, 2020

Uh oh!

SparkQA commented Apr 2, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

beliefer commented Mar 31, 2020 •

edited

Loading

beliefer Apr 1, 2020 •

edited

Loading

beliefer Apr 1, 2020 •

edited

Loading

dongjoon-hyun Apr 1, 2020 •

edited

Loading