Debug: improve reporting visited tokens

scalafmt-core/shared/src/main/scala/org/scalafmt/config/FormatEvent.scala

@@ -19,6 +19,7 @@ object FormatEvent {
  totalExplored: Int,
  finalState: State,
  visits: IndexedSeq[Int],
+ best: collection.Map[Int, State],
  ) extends FormatEvent
  case class Written(formatLocations: FormatWriter#FormatLocations)
  extends FormatEvent

scalafmt-core/shared/src/main/scala/org/scalafmt/internal/BestFirstSearch.scala

@@ -123,11 +123,13 @@ private class BestFirstSearch private (range: Set[Range])(implicit
  if (noOptZone || shouldEnterState(curr)) {
  trackState(curr, depth, Q.length)
 
- if (explored > style.runner.maxStateVisits)
+ if (explored > style.runner.maxStateVisits) {
+ complete(deepestYet)
  throw new SearchStateExploded(
  deepestYet,
  "exceeded `runner.maxStateVisits`",
  )
+ }
 
  if (curr.split != null && curr.split.isNL)
  if (
@@ -258,7 +260,7 @@ private class BestFirstSearch private (range: Set[Range])(implicit
  }
 
  private def complete(state: State)(implicit style: ScalafmtConfig): Unit =
- style.runner.event(CompleteFormat(explored, state, visits))
+ style.runner.event(CompleteFormat(explored, state, visits, best))
 
  def getBestPath: SearchResult = {
  val state = {

scalafmt-core/shared/src/main/scala/org/scalafmt/internal/FormatToken.scala

@@ -28,7 +28,7 @@ case class FormatToken(left: Token, right: Token, meta: FormatToken.Meta) {
  case 1 => "LF"
  case _ => "LFLF"
  }
- s"${meta.left.text}∙${meta.right.text}: ${left.structure} [$ws] ${right.structure}"
+ s"[$idx] ${meta.left.text}∙${meta.right.text}: ${left.structure} [$ws] ${right.structure}"
  }
 
  def inside(range: Set[Range]): Boolean =

scalafmt-tests/src/test/scala/org/scalafmt/Debug.scala

@@ -18,34 +18,32 @@ import scala.collection.mutable
  */
 class Debug(val verbose: Boolean) {
 
- var formatTokenExplored: IndexedSeq[Int] = _
  val enqueuedSplits = mutable.Set.empty[Split]
  var formatOps: FormatOps = _
- var explored = 0
- var state = State.start
+ var completedEvent: Option[CompleteFormat] = None
  var locations: FormatWriter#FormatLocations = _
- def tokens = formatOps.tokens.arr
  val startTime = System.nanoTime()
 
  def elapsedNs = System.nanoTime() - startTime
 
  def enqueued(split: Split): Unit = if (verbose) enqueuedSplits += split
 
  def completed(event: CompleteFormat): Unit = {
- explored += event.totalExplored
+ completedEvent = Option(event)
  Debug.explored += event.totalExplored
- formatTokenExplored = event.visits
- state = event.finalState
  }
 
+ def formatTokenExplored = completedEvent.map(_.visits)
+ def explored = completedEvent.map(_.totalExplored)
+
  def printTest(): Unit = {
  if (!verbose) return
 
  // splits
  if (enqueuedSplits.nonEmpty) {
  val sb = new StringBuilder()
  enqueuedSplits.groupBy(_.fileLine.line.value).toSeq.sortBy(-_._2.size)
- .iterator.take(3).foreach { case (line, group) =>
+ .iterator.take(5).foreach { case (line, group) =>
  sb.append("Split(line=").append(line).append(" count=")
  .append(group.size).append("=")
  group.foreach(sb.append("\n\t").append(_))
@@ -54,41 +52,64 @@ class Debug(val verbose: Boolean) {
  LoggerOps.logger.debug(sb.toString())
  }
 
+ completedEvent.foreach(x => Debug.printCompletedEvent(x, formatOps))
+ }
+
+}
+
+object Debug {
+
+ var explored = 0
+
+ def printCompletedEvent(
+ completedEvent: CompleteFormat,
+ formatOps: FormatOps,
+ ): Unit = {
  val toks = if (null == formatOps) null else formatOps.tokens.arr
  if (null != toks) {
- if (null != formatTokenExplored) formatTokenExplored.zipWithIndex
- .sortBy(-_._1).take(3).foreach { case (visits, idx) =>
- LoggerOps.logger.debug("Visited " + toks(idx) + ": " + visits)
+ if (null != completedEvent.visits) {
+ val sb = new StringBuilder()
+ sb.append("Visited ").append(completedEvent.totalExplored).append(":")
+ completedEvent.visits.zipWithIndex.sortBy(-_._1).take(10).foreach {
+ case (visits, idx) => sb.append("\n\t").append(visits).append(": ")
+ .append(toks(idx))
  }
+ sb.append("\n")
+ LoggerOps.logger.debug(sb.toString())
+ }
+
+ if (null != completedEvent.best) {
+ val sb = new StringBuilder()
+ sb.append("Best splits:")
+ completedEvent.best.values.toSeq.sortBy(_.depth).take(5).foreach {
+ state => sb.append("\n\t").append(LoggerOps.log(state))
+ }
+ sb.append("\n")
+ LoggerOps.logger.debug(sb.toString())
+ }
 
  val stack = new mutable.ListBuffer[String]
  val posWidth = s"%${1 + math.log10(toks.last.left.end).toInt}d"
  @tailrec
  def iter(state: State): Unit = if (state.prev ne State.start) {
  val prev = state.prev
- val tok = toks(prev.depth).left
+ val idx = prev.depth
+ val tok = toks(idx).left
  val clean = "%-15s".format(LoggerOps.cleanup(tok).slice(0, 15))
  stack.prepend(
- s"${posWidth.format(tok.end)}: $clean" +
+ s"[$idx] ${posWidth.format(tok.end)}: $clean" +
  s" ${state.split} ${prev.indentation} ${prev.column} [${state.cost}]",
  )
  iter(prev)
  }
- if (state ne State.start) {
- iter(state)
+ if (null != completedEvent.finalState) {
+ iter(completedEvent.finalState)
  stack.foreach(LoggerOps.logger.debug)
+ LoggerOps.logger.debug(s"Total cost: ${completedEvent.finalState.cost}")
  }
  }
-
- LoggerOps.logger.debug(s"Total cost: ${state.cost}")
  }
 
-}
-
-object Debug {
-
- var explored = 0
-
  def ns2ms(nanoseconds: Long): Long = TimeUnit.MILLISECONDS
  .convert(nanoseconds, TimeUnit.NANOSECONDS)
 

scalafmt-tests/src/test/scala/org/scalafmt/util/HasTests.scala

@@ -153,8 +153,8 @@ trait HasTests extends FormatAssertions {
  obtained,
  obtainedHtml,
  output,
- Option(debug.formatTokenExplored).fold(0)(_.max),
- debug.explored,
+ debug.formatTokenExplored.fold(0)(_.max),
+ debug.explored.getOrElse(0),
  debug.elapsedNs,
  )
  }
@@ -188,7 +188,7 @@ trait HasTests extends FormatAssertions {
  entry.formatWhitespace(0)
  builder += FormatOutput(
  sb.result(),
- Option(debug.formatTokenExplored).fold(-1)(_(token.meta.idx)),
+ debug.formatTokenExplored.fold(-1)(_(token.meta.idx)),
  )
  })
  builder.result()