Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[prelude][core] Frame and Log optimizations #800

Merged
merged 4 commits into from
Nov 1, 2024
Merged

[prelude][core] Frame and Log optimizations #800

merged 4 commits into from
Nov 1, 2024

Conversation

fwbrasil
Copy link
Collaborator

I noticed a major performance regression in LoggingBench. The main cause is a bug introduced by #783 that makes the benchmark consider Level.error enabled when it isn't. I fixed the bug but also worked on a few optimizations to improve performance in case the log is enabled.

Benchmark results:

image

@@ -25,34 +25,34 @@ object LogPlatformSpecific:
else Level.error

inline def trace(msg: => String)(using frame: Frame, allow: AllowUnsafe): Unit =
if Level.trace.enabled(level) then logger.trace(s"[${frame.parse.position}] $msg")
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The parse method was quite expensive since it parsed all the fields, allocating several sub-strings. I've optimized Frame to provide more lightweight methods to access the information it contains.

@@ -2,7 +2,7 @@ package kyo

import kyo.internal.LogPlatformSpecific

final case class Log(unsafe: Log.Unsafe) extends AnyVal:
final case class Log(unsafe: Log.Unsafe):
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I noticed several Log allocations in the benchmark. There are scenarios where both the compiler and the JIT fail to prevent allocation, triggering the boxing every time Log is used. By removing AnyVal, the Log is always allocated once when created and then reused. I'll take a look at making this change for the other effects as well.

@@ -67,18 +67,19 @@ object Ansi:
*/
def apply(header: String, code: String, trailer: String, startLine: Int = 1): String =
try
val headerLines = if header.nonEmpty then header.split("\n") else Array.empty[String]
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few cosmetic improvements

frame.parse.show,
"──────────────────────────────".dim
).mkString("\n")
override def getMessage() = frame.render("Check failed! ".red.bold + message)
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

New convenience frame.render for this kind of use case.

@@ -23,8 +23,8 @@ abstract class Local[A]:
* @return
* An effect that produces the current value
*/
final def get(using Frame): A < Any =
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These weren't inlined I believe because of compilation issues since we typically inline suspension methods. I've made State public and was able to inline the methods.

if end < 0 then self.substring(start)
else self.substring(start, end)

def position: Position = self
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note that there's no allocation when frame.position is called. It's just a wrapper that provides methods to read the specific fields.

self.substring(start)
end snippet

def snippetShort: String = snippet.split("📍")(0).reverse.take(snippetShortMaxChars).takeWhile(_ != '\n').trim.reverse
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this expensive string transformation was being done on each benchmark iteration 😱

@@ -9,45 +9,88 @@ opaque type Frame <: AnyRef = String

object Frame:

private val version = '0'
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've added a version field as the first character of the Frame payload so we can more easily make changes to the format in the future.

@@ -17,42 +17,42 @@ object LogPlatformSpecific:
def apply(name: String) = new SLF4J(org.slf4j.LoggerFactory.getLogger(name))

class SLF4J(logger: org.slf4j.Logger) extends Log.Unsafe:
def level =
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The main bug was here. The logic was inverted.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think this can be a val - it will be transient for an slf4j logger based on ThreadLocal? Not that I rely on that feature...

Copy link
Collaborator Author

@fwbrasil fwbrasil Oct 31, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it'd be an issue only if the SLF4J config dynamically changes at runtime. I've never used such a feature, I'm not sure if it's possible or how useful it'd be. I made it a val because, in theory, we'd need an IO suspension to read the level otherwise.

@@ -17,42 +17,42 @@ object LogPlatformSpecific:
def apply(name: String) = new SLF4J(org.slf4j.LoggerFactory.getLogger(name))

class SLF4J(logger: org.slf4j.Logger) extends Log.Unsafe:
def level =
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think this can be a val - it will be transient for an slf4j logger based on ThreadLocal? Not that I rely on that feature...

val trailerLines = if trailer.nonEmpty then trailer.split("\n") else Array.empty[String]
val separatorLine = "─".repeat(30).dim
val headerLines = if header.nonEmpty then Array(separatorLine) ++ header.split("\n") else Array.empty[String]
val codeLines = code.split("\n").dropWhile(_.trim.isEmpty).reverse.dropWhile(_.trim.isEmpty).reverse
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

.isBlank should avoid new string allocations.

@fwbrasil fwbrasil mentioned this pull request Oct 31, 2024
hearnadam pushed a commit that referenced this pull request Oct 31, 2024
Following up on
#800 (comment). Since
Scala 3 doesn't have specialization `AnyVal` values can keep boxing on
every transformation.
Copy link
Collaborator

@hearnadam hearnadam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice work!

@fwbrasil fwbrasil merged commit 17e5646 into main Nov 1, 2024
3 checks passed
@fwbrasil fwbrasil deleted the frame-log-opt branch November 1, 2024 04:15
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants