Skip to content

Latest commit

ย 

History

History
166 lines (98 loc) ยท 3.16 KB

Measuring Performance Using Logging.md

File metadata and controls

166 lines (98 loc) ยท 3.16 KB
Raw

Measuring Performance Using Logging

@ WWDC 18

Your mission: Improve Performance

Introducing Signposts

  • Signposts
    • Part of the os_log family
    • Performance-focused time markers
  • Instruments
    • Aggregate and analyze signpost data
    • Visualize activity over time

Logging

let logHandle = OSLog(subsystem: "com.example.widget", category: "Setup")
os_log(.info, log: logHandle, "Hello, %{public}s!", world)

  • Our new logging system was introduced at WWDC 2016

    • Built for debugging with efficiency and privacy in mind

  • Signposts created for investigating performance

    • Built for performance use case and integration with developer tools

Signpost Names

os_signpost(.begin, log: refreshLog, name: "Fetch Asset")
os_signpost(.end, log: refreshLog, name: "Fetch Asset")
  • The string literal identifies signpost intervals
  • The name must match at .begin, .end

Signpost IDs

let spid = OSSignpostID(log: refreshLog)
os_signpost(.begin, log: refreshLog, name: "Fetch Asset", signpostID: spid)
os_singpost(.end, log: refreshLog, name: "Fetch Asset", signpostID: spid)
  • Use signpost IDs to tell overlapping operations apart
  • While running, use the same IDs for each pair of .begin, .end

image

Custom Metadata in Signpost Arguments

os_signpost(.begin, log: log, name: "Compute Physics", "for particle")
os_signpost(.begin, log: log, name: "Compute Physics", "%d %d %d %d", x1, y1, x2, y2)

  • Add context to the .begin, .end

  • Pass arguments with os_log format string literal

  • Pass many arguments with different types

  • Pass dynamic strings

  • The format string is a fixed cost, so feel free to be descriptive!

image

Signpost Events

os_signpost(.event, log: log, name: "Fetch Asset", "Fetched first chunk, size %u", size)
os_signpost(.event, log: log, name: "Swipe", "For action 0x%x", actionCode)
  • Marking a single point in time

Signposts Are Lightweight

  • Built to minimize observer effect
  • Built for fine-grained measurement in a short time span

Enabling and Disabling Signpost Categories

OSLog.disabled
  • Take advantage of special log handle
  • Just change the handle - can leave calling sites alone
let refreshLog: OSLog
if ProcessInfo.processInfo.environment.keys.contains("SIGNPOSTS_FOR_REFRESH") {
  refreshLog = OSLog(subsystem: "com.example.your-app", category: "RefreshOperations")
} else {
  refreshLog = .disabled
}

Instrumentation-Specific Code

if refreshLog.signpostsEnabled {
  let information = copyDescription()
  os_signpost(..., information)
}
  • For additional expensive code that is only useful for the signpost

Signposts in C

image

Instruments 10

  • os_signpost
  • Points of Interest
  • Custom instruments

Summary

  • Annotate code with signposts
    • Easily mark intervals
    • Capture metadata of interest
  • Use Instruments to view signpost data
    • Visualize where time is spent
    • Understand what program is doing