Skip to content

Commit 9141aa4

Browse files
committed
[SPARK-48744][CORE] Log entry should be constructed only once
### What changes were proposed in this pull request? In the current implementation: ``` class LogEntry(messageWithContext: => MessageWithContext) { def message: String = messageWithContext.message def context: java.util.HashMap[String, String] = messageWithContext.context } def logInfo(entry: LogEntry): Unit = { if (log.isInfoEnabled) { withLogContext(entry.context) { log.info(entry.message) } } } ``` The field `messageWithContext` is constructed twice, one from `entry.context` and another one from `entry.message`. This PR is to improve this and ensure a log entry is constructed only once. ### Why are the changes needed? Improve the performance of logging ### Does this PR introduce _any_ user-facing change? No ### How was this patch tested? New UT ### Was this patch authored or co-authored using generative AI tooling? No Closes #47135 from gengliangwang/addCache. Authored-by: Gengliang Wang <[email protected]> Signed-off-by: Gengliang Wang <[email protected]>
1 parent 2eeebef commit 9141aa4

File tree

2 files changed

+36
-3
lines changed

2 files changed

+36
-3
lines changed

common/utils/src/main/scala/org/apache/spark/internal/Logging.scala

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -99,9 +99,11 @@ case class MessageWithContext(message: String, context: java.util.HashMap[String
9999
* Companion class for lazy evaluation of the MessageWithContext instance.
100100
*/
101101
class LogEntry(messageWithContext: => MessageWithContext) {
102-
def message: String = messageWithContext.message
102+
private lazy val cachedMessageWithContext: MessageWithContext = messageWithContext
103103

104-
def context: java.util.HashMap[String, String] = messageWithContext.context
104+
def message: String = cachedMessageWithContext.message
105+
106+
def context: java.util.HashMap[String, String] = cachedMessageWithContext.context
105107
}
106108

107109
/**

common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala

Lines changed: 32 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@ import com.fasterxml.jackson.module.scala.DefaultScalaModule
2525
import org.apache.logging.log4j.Level
2626
import org.scalatest.funsuite.AnyFunSuite // scalastyle:ignore funsuite
2727

28-
import org.apache.spark.internal.{LogEntry, Logging, LogKey, LogKeys, MDC}
28+
import org.apache.spark.internal.{LogEntry, Logging, LogKey, LogKeys, MDC, MessageWithContext}
2929

3030
trait LoggingSuiteBase
3131
extends AnyFunSuite // scalastyle:ignore funsuite
@@ -228,6 +228,37 @@ trait LoggingSuiteBase
228228
verifyMsgWithConcat(level, logOutput)
229229
}
230230
}
231+
232+
test("LogEntry should construct MessageWithContext only once") {
233+
var constructionCount = 0
234+
235+
def constructMessageWithContext(): MessageWithContext = {
236+
constructionCount += 1
237+
log"Lost executor ${MDC(LogKeys.EXECUTOR_ID, "1")}."
238+
}
239+
logInfo(constructMessageWithContext())
240+
assert(constructionCount === 1)
241+
}
242+
243+
test("LogEntry should construct MessageWithContext only once II") {
244+
var constructionCount = 0
245+
var constructionCount2 = 0
246+
247+
def executorId(): String = {
248+
constructionCount += 1
249+
"1"
250+
}
251+
252+
def workerId(): String = {
253+
constructionCount2 += 1
254+
"2"
255+
}
256+
257+
logInfo(log"Lost executor ${MDC(LogKeys.EXECUTOR_ID, executorId())}." +
258+
log"worker id ${MDC(LogKeys.WORKER_ID, workerId())}")
259+
assert(constructionCount === 1)
260+
assert(constructionCount2 === 1)
261+
}
231262
}
232263

233264
class StructuredLoggingSuite extends LoggingSuiteBase {

0 commit comments

Comments
 (0)