[SPARK-20871][SQL] limit logging of Janino code #18658

pjfanning · 2017-07-17T17:08:22Z

What changes were proposed in this pull request?

When the code that is generated is greater than 64k, then Janino compile will fail and CodeGenerator.scala will log the entire code at Error level.
SPARK-20871 suggests only logging the code at Debug level.
Since, the code is already logged at debug level, this Pull Request proposes not including the formatted code in the Error logging and exception message at all.
When an exception occurs, the code will be logged at Info level but truncated if it is more than 1000 lines long.

How was this patch tested?

Existing tests were run.
An extra test test case was added to CodeFormatterSuite to test the new maxLines parameter,

ash211 · 2017-07-17T17:42:19Z

Jenkins this is ok to test

marmbrus · 2017-07-17T19:21:33Z

I don't have super strong opinions here, but in my experience its not always easy to get users to rerun a failed query with a different logging level. Have we considered truncating or special casing the 64k limitation instead?

pjfanning · 2017-07-17T19:31:53Z

@marmbrus How about something like?:

        val msg = s"failed to compile: $e"
        logError(msg, e)
        logInfo(formatted)
        throw new JaninoRuntimeException(msg, e)

Users with info logging enabled would get the code output when an issue arises but users who don't want to log the code could apply a log level of Warn or Error to the class.
If we are going to output the code, then it feels like we should output it all for completeness. I don't have a strong opinion on this latter point though. There is an alternate argument that for large code, then outputting a truncated version might be enough.

marmbrus · 2017-07-17T19:35:04Z

That seems reasonable. I'm kind of pro-truncation for very very large code. Even though its not great to have something truncated, outputting GBs of logs is also pretty bad for downstream consumers.

SparkQA · 2017-07-17T20:25:08Z

Test build #79677 has finished for PR 18658 at commit 803166c.

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

ash211 · 2017-07-17T20:40:08Z

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

      // Only add extra debugging info to byte code when we are going to print the source code.
      evaluator.setDebuggingInformation(true, true, false)
-      s"\n$formatted"
+      s"\n${CodeFormatter.format(code)}"


I'd suggest dropping the string concatenation with \n here -- it requires an additional copy of the code to be held in-memory and for errors where the code is too long, this causes unnecessary additional pressure on the heap

@ash211 the logging will be less user friendly without the \n and this is debug logging - I am working on an enhancement to the CodeFormatter class for the info level logging discussed earlier with @marmbrus that would allow a max number of lines to be specified

ash211 · 2017-07-17T20:40:34Z

FYI for future reviewers as well, we've been running an extremely similar patch to PJ's on our distribution of Spark for the past several months and had no problems.

Without this change, a code compilation failure often escalates into a heap OOM as the too-large source code is replicated in memory through the log statement.

…f 1000 lines)

SparkQA · 2017-07-18T00:51:08Z

Test build #79683 has finished for PR 18658 at commit 52b20f3.

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

pjfanning · 2017-07-20T22:28:29Z

@ash211 , @marmbrus does this Pull Request look ok or are there other changes needed?

gatorsmile · 2017-07-21T02:59:26Z

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

-        val msg = s"failed to compile: $e\n$formatted"
+        val msg = s"failed to compile: $e"
        logError(msg, e)
+        logInfo(s"\n${CodeFormatter.format(code, 1000)}")


1000 -> maxLines = 1000

gatorsmile · 2017-07-21T02:59:41Z

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

-        val msg = s"failed to compile: $e\n$formatted"
+        val msg = s"failed to compile: $e"
        logError(msg, e)
+        logInfo(s"\n${CodeFormatter.format(code, 1000)}")


The same here

gatorsmile · 2017-07-21T03:03:21Z

When the size is too large, which exception will be thrown?

Truncate for all the cases? or just when the size is too large?

pjfanning · 2017-07-21T08:49:02Z

@gatorsmile I made the change you requested.
The idea is that when we log the code when the exceptions happen, that we don't want to print the entire code for very large examples. There is still debug level logging that will print the entire code.
I'm pretty neutral about the limit and if it is necessary at all. My main aim is have the code logging done at a different level from the error message so that I can configure my log settings to not log the code at all. I work on a SaaS solution and we don't our user's code to appear in our logs.

srowen · 2017-07-21T09:10:43Z

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

-  def format(code: CodeAndComment): String = {
+  def format(code: CodeAndComment): String = format(code, -1)
+
+  def format(code: CodeAndComment, maxLines: Int): String = {


Can maxLines just be an optional argument rather than declare two methods? this is an internal method so its signature is OK to change.

@srowen I can make that change. Is there any need to scaladoc the maxLines param? Or is the function definition easy enough to follow?

def format(code: CodeAndComment, maxLines: Int = -1): String

SparkQA · 2017-07-21T11:08:48Z

Test build #79830 has finished for PR 18658 at commit 2997ded.

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

…ed for maxLines

SparkQA · 2017-07-21T14:47:00Z

Test build #79834 has finished for PR 18658 at commit 252f8ea.

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

gatorsmile · 2017-07-22T22:19:32Z

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

-        val msg = s"failed to compile: $e\n$formatted"
+        val msg = s"failed to compile: $e"
        logError(msg, e)
+        logInfo(s"\n${CodeFormatter.format(code, maxLines = 1000)}")


My only concern whether we should add an internal SQLConf for this hard-coded value.

@gatorsmile I can add a config item to org.apache.spark.sql.internal.SQLConf.scala if you think this is appropriate.
Maybe something like:

val CODEGEN_LOGGING_MAX_LINES = buildConf("spark.sql.codegen.logging.maxLines") .internal() .doc("The maximum number of codegen lines to log when errors occur.") .intConf .createWithDefault(1000)

Looks fine to me

…ogging.maxLines

SparkQA · 2017-07-23T02:08:50Z

Test build #79871 has finished for PR 18658 at commit c42dc46.

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

gatorsmile · 2017-07-23T05:12:25Z

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

-        val msg = s"failed to compile: $e\n$formatted"
+        val msg = s"failed to compile: $e"
        logError(msg, e)
+        val maxLines = new SQLConf().loggingMaxLinesForCodegen


-> SQLConf.get.loggingMaxLinesForCodegen

gatorsmile · 2017-07-23T05:12:47Z

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

-        val msg = s"failed to compile: $e\n$formatted"
+        val msg = s"failed to compile: $e"
        logError(msg, e)
+        val maxLines = new SQLConf().loggingMaxLinesForCodegen


-> SQLConf.get.loggingMaxLinesForCodegen

gatorsmile · 2017-07-23T05:13:23Z

sql/catalyst/src/main/scala/org/apache/spark/sql/internal/SQLConf.scala

+  val CODEGEN_LOGGING_MAX_LINES = buildConf("spark.sql.codegen.logging.maxLines")
+    .internal()
+    .doc("The maximum number of codegen lines to log when errors occur.")
+    .intConf


Add checkValue

…codegen.logging.maxLines

pjfanning · 2017-07-23T08:22:32Z

@gatorsmile I've made the changes you requested.

SparkQA · 2017-07-23T10:24:06Z

Test build #79882 has finished for PR 18658 at commit a795db2.

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

gatorsmile · 2017-07-23T17:37:29Z

LGTM

gatorsmile · 2017-07-23T17:38:29Z

Thanks! Merging to master.

[SPARK-20871] only log Janino code at debug level

803166c

pjfanning changed the title ~~[SPARK-20871] only log Janino code at debug level~~ [SPARK-20871][SQL] only log Janino code at debug level Jul 17, 2017

ash211 reviewed Jul 17, 2017

View reviewed changes

[SPARK-20871][SQL] log Janino code at info level (but include a max o…

52b20f3

…f 1000 lines)

pjfanning changed the title ~~[SPARK-20871][SQL] only log Janino code at debug level~~ [SPARK-20871][SQL] limit logging of Janino code Jul 17, 2017

gatorsmile reviewed Jul 21, 2017

View reviewed changes

Explicitly reference the maxLines param

2997ded

srowen reviewed Jul 21, 2017

View reviewed changes

[SPARK-20871][SQL] have just one format function with a default appli…

252f8ea

…ed for maxLines

srowen approved these changes Jul 22, 2017

View reviewed changes

gatorsmile reviewed Jul 22, 2017

View reviewed changes

[SPARK-20871][SQL] add SQLConf internal property: spark.sql.codegen.l…

c42dc46

…ogging.maxLines

gatorsmile reviewed Jul 23, 2017

View reviewed changes

[SPARK-20871][SQL] add check on SQLConf internal property: spark.sql.…

a795db2

…codegen.logging.maxLines

asfgit closed this in 2a53fbf Jul 23, 2017

pjfanning deleted the SPARK-20871 branch July 23, 2017 19:12

gatorsmile mentioned this pull request Aug 7, 2017

[SPARK-21603][SQL]The wholestage codegen will be much slower then that is closed when the function is too long #18810

Closed

[SPARK-20871][SQL] limit logging of Janino code #18658

[SPARK-20871][SQL] limit logging of Janino code #18658

Uh oh!

Conversation

pjfanning commented Jul 17, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What changes were proposed in this pull request?

How was this patch tested?

Uh oh!

ash211 commented Jul 17, 2017

Uh oh!

marmbrus commented Jul 17, 2017

Uh oh!

pjfanning commented Jul 17, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

marmbrus commented Jul 17, 2017

Uh oh!

SparkQA commented Jul 17, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ash211 commented Jul 17, 2017

Uh oh!

SparkQA commented Jul 18, 2017

Uh oh!

pjfanning commented Jul 20, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

gatorsmile commented Jul 21, 2017

Uh oh!

pjfanning commented Jul 21, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

SparkQA commented Jul 21, 2017

Uh oh!

SparkQA commented Jul 21, 2017

Uh oh!

gatorsmile Jul 22, 2017 • 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!

SparkQA commented Jul 23, 2017

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!

pjfanning commented Jul 23, 2017

Uh oh!

SparkQA commented Jul 23, 2017

Uh oh!

gatorsmile commented Jul 23, 2017

Uh oh!

gatorsmile commented Jul 23, 2017

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

pjfanning commented Jul 17, 2017 •

edited

Loading

pjfanning commented Jul 17, 2017 •

edited

Loading

gatorsmile Jul 22, 2017 •

edited

Loading