Logging and diagnostics

Goldberry logs through SLF4J and binds nothing. Add a provider and the start-up timeline, the frame timings and the platform's own libraries appear under names you can level.

By the end of this chapter you can see where a slow start or a slow frame went, silence a native library by name, read which way a window presents, set the properties that change the toolkit’s behaviour at run time, and recognise the failure messages that come up most.

runtimeOnly 'ch.qos.logback:logback-classic:1.6.3'

Add nothing and you get silence, including from SLF4J itself, which would otherwise print a “no providers were found” warning (ADR-0023). Binding a provider is an application’s decision and never a library’s.

A logback configuration

<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder><pattern>%d{HH:mm:ss.SSS} %-5level %logger{0} - %msg%n</pattern></encoder>
  </appender>

  <!-- The toolkit. DEBUG is the window lifecycle and backend start-up;
       TRACE adds the start-up timeline and a line per frame. -->
  <logger name="dev.goldberry" level="${goldberry.log.level:-DEBUG}"/>

  <!-- What the platform's own libraries say (ADR-0443). -->
  <logger name="native" level="warn"/>
  <logger name="native.glib.libayatana-appindicator" level="off"/>

  <root level="INFO"><appender-ref ref="CONSOLE"/></root>
</configuration>

goldberry.log.level is a variable this file reads, not a property the toolkit knows. The showcase’s logback.xml is the one above, and -Dgoldberry.log.level=TRACE is how its run switches the toolkit to trace.

The start-up timeline

At TRACE, one table is printed after the first frame (ADR-0028):

start-up timeline (866.6ms to here):
     533.8ms    +533.8ms  runtime starting
     559.6ms     +25.8ms  libgoldberry mapped (1.9ms)
     722.6ms    +162.9ms  SDL video subsystem up (99.2ms)
     866.6ms    +117.1ms  first frame presented

Each phase is measured from process start, so the first row says how long the JVM took before the toolkit saw a line of your code. Startup.mark("my phase") and Startup.time("my phase", work) add your own rows, and Startup.sinceProcessStart() is what the showcase’s status bar reads. What the numbers should be, and how to make them smaller, is in Starting fast.

Frames

At TRACE, every painted frame logs one line:

frame 312 in 1840us: buffer 12, paint 1105 (begin 40, draw 980, end 85), present 723

The stage timings are FrameStats, which host.frames() reads live and a hud draws on screen. Two properties go deeper, and both are properties rather than log levels because a diagnostic that costs an isTraceEnabled() per element per frame would be measuring itself:

• -Dgoldberry.trace.frames=true counts what each frame did to the element tree: elements built, styles resolved, subtrees thrown away. =all reports the quiet frames too.
• -Dgoldberry.trace.input=true reports every pseudo-class the pointer and the keyboard set, one line per node of the chain.

Measuring says what to do with the numbers.

The platform’s own libraries

GLib and SDL used to log to stderr, past SLF4J and past your configuration. Their messages are ordinary SLF4J events now, on native.<library>.<subsystem>: native.glib.libayatana-appindicator, native.sdl.video (ADR-0443). Level, route or switch them off by name like anything else.

-Dgoldberry.log.native=false installs no bridge and gives each library its stderr back, which is what to reach for when something in the platform layer is being debugged and a logging configuration might be hiding it. -Dgoldberry.log.glib.writer=true also installs a GLib structured-log writer, only if nothing else in the process sets one.

Which way a window presents

Each window logs one line at INFO when it starts presenting a different way, tagged [GPU] or [CPU], with the reason (ADR-0492). The same fact is window.presentation(), with label() for a status bar, and onPresentationChange(listener) for a change mid-run: a GPU that failed, or goldberry.gpu.composite=auto taking the GPU for a layer and giving it back.

What this build can do

Set<Capability> can = Goldberry.capabilities();

The desktop integrations are compiled into the native library only where the machine that built it had the headers. Goldberry.capabilities() answers from the library’s own record, before any window is open, and is empty where there is no native library at all (ADR-0325). The values are in Windows, popups and the host.

Properties an application can set

All read with -Dname=value on the command line, or set before the toolkit starts.

goldberry.golden.update, goldberry.golden.scales, goldberry.gpu.required and the other *.required properties belong to this repository’s own test tasks and do nothing in an application.

Failure messages, and what they mean

Read more

• ADR-0023: SLF4J, binding none
• ADR-0028: the start-up timeline
• ADR-0443: native logs bridged
• ADR-0492: the presentation line
• Measuring: the HUD and the benchmarks