Improved the startup analysis scripts.

* Deduplicated code between the analyzer and summarizer
* Improved some code reliability
* Collected additional information

Test: Compiled
Test: Ran analyzer on several sample files
Test: Processed 6400 trace files with the summarizer
Change-Id: I8604d375890144db0f3359551c11ebe6cfb7ab8b

4 files changed, 483 insertions, 318 deletions

diff --git a/core/common/src/main/kotlin/trebuchet/queries/SliceQueries.kt b/core/common/src/main/kotlin/trebuchet/queries/SliceQueries.kt
index c464e7b..70d5b34 100644
--- a/core/common/src/main/kotlin/trebuchet/queries/SliceQueries.kt
+++ b/core/common/src/main/kotlin/trebuchet/queries/SliceQueries.kt
@@ -64,6 +64,16 @@ object SliceQueries {
         return ret
     }
 
+    fun selectAll(process : ProcessModel, cb : (Slice) -> Boolean) : List<Slice> {
+        val ret = mutableListOf<Slice>()
+        iterSlices(process) {
+            if (cb(it)) {
+                ret.add(it)
+            }
+        }
+        return ret
+    }
+
     fun selectAll(thread: ThreadModel, cb: (Slice) -> Boolean): List<Slice> {
         val ret = mutableListOf<Slice>()
         iterSlices(thread) {
@@ -74,11 +84,52 @@ object SliceQueries {
         return ret
     }
 
+    fun selectFirst(model: Model, cb: (Slice) -> Boolean) : Slice? {
+        return model.processes.values.mapNotNull { selectFirst(it, cb) }.minBy { it.startTime }
+    }
+
+    fun selectFirst(process: ProcessModel, cb: (Slice) -> Boolean) : Slice? {
+        var ret : Slice? = null
+
+        process.asyncSlices.forEach {
+            if (cb(it)) {
+                ret = it
+                return@forEach
+            }
+        }
+
+        process.threads.forEach { thread ->
+            val threadSlice = selectFirst(thread, cb)
+
+            if (threadSlice != null && (ret == null || threadSlice.startTime < ret!!.startTime)) {
+                ret = threadSlice
+            }
+        }
+
+        return ret
+    }
+
+    fun selectFirst(thread : ThreadModel, cb : (Slice) -> Boolean) : Slice? {
+        var ret : Slice? = null
+        iterSlices(thread) {
+            if (cb(it)) {
+                ret = it
+                return@iterSlices
+            }
+        }
+        return ret
+    }
+
     fun traverseSlices(model: Model, cb: SliceTraverser) {
         model.processes.values.forEach { traverseSlices(it, cb) }
     }
 
     fun traverseSlices(process: ProcessModel, cb: SliceTraverser) {
+        process.asyncSlices.forEach {
+            cb.beginSlice(it)
+            cb.endSlice(it)
+        }
+
         process.threads.forEach { traverseSlices(it, cb) }
     }
 
@@ -100,6 +151,7 @@ object SliceQueries {
     }
 
     fun iterSlices(process: ProcessModel, cb: (Slice) -> Unit) {
+        process.asyncSlices.forEach { cb(it) }
         process.threads.forEach { iterSlices(it, cb) }
     }
 
diff --git a/trebuchet/startup-analyzer/src/StartupAnalyzer.kt b/trebuchet/startup-analyzer/src/StartupAnalyzer.kt
index 5a06c76..cdc93b0 100644
--- a/trebuchet/startup-analyzer/src/StartupAnalyzer.kt
+++ b/trebuchet/startup-analyzer/src/StartupAnalyzer.kt
@@ -27,11 +27,6 @@
 import java.io.File
 import trebuchet.model.Model
 import trebuchet.extras.parseTrace
-import trebuchet.model.base.Slice
-import trebuchet.queries.SliceQueries
-import trebuchet.queries.SliceTraverser
-import trebuchet.queries.TraverseAction
-import kotlin.system.exitProcess
 
 /*
  * Constants
@@ -45,137 +40,54 @@ import kotlin.system.exitProcess
  * Class Extensions
  */
 
-//private fun Double.secondValueToMillisecondString() = "%.3f ms".format(this * 1000.0)
-
-private fun <K, V> MutableMap<K, MutableList<V>>.add(key: K, el: V) {
-    this.getOrPut(key) { mutableListOf() }.add(el)
-}
-
 /*
  * Helper Functions
  */
 
 fun measureStartup(model: Model) {
-    val systemServerIDs = model.findIDsByName(PROC_NAME_SYSTEM_SERVER)
-
-    if (systemServerIDs == null) {
-        println("Error: Unable to find the System Server")
-        exitProcess(1)
-    }
+    val startupEvents = model.getStartupEvents()
 
-    val systemServerProc = model.processes[systemServerIDs.first]
-    val startedApps: MutableMap<Int, Pair<String, Double>> = mutableMapOf()
+    println("Found ${startupEvents.count()} startup events.")
 
-    systemServerProc!!.threads.forEach { thread ->
-        SliceQueries.iterSlices(thread) { slice ->
-            if (slice.name.startsWith(SLICE_NAME_PROC_START)) {
-
-                val newProcName = slice.name.split(':', limit = 2)[1].trim()
-                val newProcIDs = model.findIDsByName(newProcName)
-
-                when {
-                    newProcIDs == null -> println("Unable to find PID for process `$newProcName`")
-                    startedApps.containsKey(newProcIDs.first) -> println("PID already mapped to started app")
-                    else -> startedApps[newProcIDs.first] = Pair(newProcName, slice.startTime)
-                }
-            }
+    startupEvents.forEach { startupEvent ->
+        println()
+        println("App Startup summary for ${startupEvent.name} (${startupEvent.proc.id}):")
+        println("\tStart offset:              ${(startupEvent.startTime - model.beginTimestamp).secondValueToMillisecondString()}")
+        println("\tLaunch duration:           ${(startupEvent.endTime - startupEvent.startTime).secondValueToMillisecondString()}")
+
+        if (startupEvent.reportFullyDrawnTime == null) {
+            println("\tRFD duration:              N/A")
+        } else {
+            println("\tRFD duration:              ${(startupEvent.reportFullyDrawnTime!! - startupEvent.startTime).secondValueToMillisecondString()}")
         }
-    }
-
-    startedApps.forEach { pid, (startedName, startupStartTime) ->
-        val process = model.processes[pid]
-        val mainThread = process!!.threads[0]
-
-        val startupEndTime = model.getStartupEndTime(mainThread, startupStartTime)
-        var unallocatedTime = 0.0
-
-        val topLevelSlices = mutableMapOf<String, MutableList<Double>>()
-
-        // Triple := Duration, Duration Self, Payload
-        val allSlices = mutableMapOf<String, MutableList<Triple<Double, Double, String?>>>()
-
-        SliceQueries.traverseSlices(mainThread, object : SliceTraverser {
-            // Our depth down an individual tree in the slice forest.
-            var treeDepth = -1
-
-            var lastTopLevelSlice : Slice? = null
-
-            override fun beginSlice(slice: Slice): TraverseAction {
-                ++this.treeDepth
-
-                if (slice.startTime < startupEndTime.timestamp) {
-                    // This slice starts during the startup period.  If it
-                    // ends within the startup period we will record info
-                    // from this slice.  Either way we will visit its
-                    // children.
-
-                    if (this.treeDepth == 0 && this.lastTopLevelSlice != null) {
-                        unallocatedTime += (slice.startTime - this.lastTopLevelSlice!!.endTime)
-                    }
-
-                    if (slice.endTime <= startupEndTime.timestamp) {
-
-                        val sliceInfo = parseSliceInfo(slice.name)
-
-                        allSlices.add(sliceInfo.type, Triple(slice.duration, slice.durationSelf, sliceInfo.payload))
-                        if (this.treeDepth == 0) topLevelSlices.add(sliceInfo.type, slice.duration)
-                    }
-
-                    return TraverseAction.VISIT_CHILDREN
-
-                } else {
-                    // All contents of this slice occur after the startup
-                    // period has ended. We don't need to record anything
-                    // or traverse any children.
-                    return TraverseAction.DONE
-                }
-            }
-
-            override fun endSlice(slice: Slice) {
-                if (this.treeDepth == 0) {
-                    lastTopLevelSlice = slice
-                }
-
-                --this.treeDepth
-            }
-        })
 
+        println("\tServer fork time:          ${startupEvent.serverSideForkTime.secondValueToMillisecondString()}")
+        println("\tTime to first slice:       ${(startupEvent.firstSliceTime - startupEvent.startTime).secondValueToMillisecondString()}")
+        println("\tUndifferentiated time:     ${startupEvent.undifferentiatedTime.secondValueToMillisecondString()}")
+        println()
+        println("\tScheduling timings:")
+        startupEvent.schedTimings.toSortedMap().forEach { schedState, timing ->
+            println("\t\t${schedState.friendlyName}: ${timing.secondValueToMillisecondString()}")
+        }
         println()
-        println("App Startup summary for $startedName (${process.id}):")
-        println("\tStart offset:              ${(startupStartTime - model.beginTimestamp).secondValueToMillisecondString()}")
-        println("\tStartup period end point:  ${startupEndTime.signal}")
-        println("\tTime to first slice:       ${(mainThread.slices.first().startTime - startupStartTime).secondValueToMillisecondString()}")
-        println("\tStartup duration:          ${(startupEndTime.timestamp - startupStartTime).secondValueToMillisecondString()}")
-        println("\tUnallocated time:          ${unallocatedTime.secondValueToMillisecondString()}")
         println("\tTop-level slice information:")
-        topLevelSlices.toSortedMap(java.lang.String.CASE_INSENSITIVE_ORDER).forEach { sliceType, eventDurations ->
-            println("\t\t$sliceType")
-            println("\t\t\tEvent count:    ${eventDurations.count()}")
-            println("\t\t\tTotal duration: ${eventDurations.sum().secondValueToMillisecondString()}")
+        startupEvent.topLevelSliceInfo.toSortedMap(java.lang.String.CASE_INSENSITIVE_ORDER).forEach { sliceName, aggInfo ->
+            println("\t\t$sliceName")
+            println("\t\t\tEvent count:    ${aggInfo.count}")
+            println("\t\t\tTotal duration: ${aggInfo.totalTime.secondValueToMillisecondString()}")
         }
         println()
         println("\tAll slice information:")
-        allSlices.toSortedMap(java.lang.String.CASE_INSENSITIVE_ORDER).forEach { sliceType, eventList ->
-            println("\t\t$sliceType")
-            println("\t\t\tEvent count:           ${eventList.count()}")
-
-            var totalDuration = 0.0
-            var totalDurationSelf = 0.0
-            var numSliceDetails = 0
-
-            eventList.forEach { (duration, durationSelf, details) ->
-                totalDuration += duration
-                totalDurationSelf += durationSelf
-                if (details != null) ++numSliceDetails
-            }
+        startupEvent.allSlicesInfo.toSortedMap(java.lang.String.CASE_INSENSITIVE_ORDER).forEach { sliceName, aggInfo->
+            println("\t\t$sliceName")
+            println("\t\t\tEvent count:           ${aggInfo.count}")
 
-            println("\t\t\tTotal duration:        ${totalDuration.secondValueToMillisecondString()}")
-            println("\t\t\tTotal duration (self): ${totalDurationSelf.secondValueToMillisecondString()}")
+            println("\t\t\tTotal duration:        ${aggInfo.totalTime.secondValueToMillisecondString()}")
 
-            if (numSliceDetails > 0) {
+            if (aggInfo.values.count() > 0) {
                 println("\t\t\tEvent details:")
-                eventList.forEach { (duration, _, details) ->
-                    if (details != null) println("\t\t\t\t$details @ ${duration.secondValueToMillisecondString()}")
+                aggInfo.values.toSortedMap(java.lang.String.CASE_INSENSITIVE_ORDER).forEach { value, (count, duration) ->
+                    println("\t\t\t\t$value ${if (count > 1) "x $count " else ""}@ ${duration.secondValueToMillisecondString()}")
                 }
             }
         }
@@ -196,6 +108,7 @@ fun main(args: Array<String>) {
     val filename = args[0]
 
     println("Opening `$filename`")
-    val trace = parseTrace(File(filename))
+    val trace = parseTrace(File(filename), verbose = false)
+
     measureStartup(trace)
 }
\ No newline at end of file
diff --git a/trebuchet/startup-common/src/StartupCommon.kt b/trebuchet/startup-common/src/StartupCommon.kt
index 99e01a4..da6c378 100644
--- a/trebuchet/startup-common/src/StartupCommon.kt
+++ b/trebuchet/startup-common/src/StartupCommon.kt
@@ -26,12 +26,12 @@
  */
 
 import trebuchet.model.Model
-import trebuchet.model.ThreadModel
+import trebuchet.model.ProcessModel
+import trebuchet.model.SchedulingState
 import trebuchet.model.base.Slice
 import trebuchet.queries.SliceQueries
 import trebuchet.queries.SliceTraverser
 import trebuchet.queries.TraverseAction
-import java.lang.Double.min
 
 /*
  * Constants
@@ -50,28 +50,33 @@ const val SLICE_NAME_ACTIVITY_START = "activityStart"
 const val SLICE_NAME_ACTIVITY_THREAD_MAIN = "ActivityThreadMain"
 const val SLICE_NAME_APP_IMAGE_INTERN_STRING = "AppImage:InternString"
 const val SLICE_NAME_APP_IMAGE_LOADING = "AppImage:Loading"
+const val SLICE_NAME_APP_LAUNCH = "launching"
 const val SLICE_NAME_ALTERNATE_DEX_OPEN_START = "Dex file open"
 const val SLICE_NAME_BIND_APPLICATION = "bindApplication"
+const val SLICE_NAME_DRAWING = "drawing"
 const val SLICE_NAME_INFLATE = "inflate"
 const val SLICE_NAME_OPEN_DEX_FILE_FUNCTION = "std::unique_ptr<const DexFile> art::OatDexFile::OpenDexFile(std::string *) const"
 const val SLICE_NAME_OBFUSCATED_TRACE_START = "X."
 const val SLICE_NAME_POST_FORK = "PostFork"
 const val SLICE_NAME_PROC_START = "Start proc"
-const val SLICE_NAME_REPORT_FULLY_DRAWN = "reportFullyDrawn"
+const val SLICE_NAME_REPORT_FULLY_DRAWN = "ActivityManager:ReportingFullyDrawn"
 const val SLICE_NAME_ZYGOTE_INIT = "ZygoteInit"
 
 val SLICE_MAPPERS = arrayOf(
     Regex("^(Collision check)"),
+    Regex("^(launching):\\s+([\\w\\.])+"),
     Regex("^(Lock contention).*"),
     Regex("^(monitor contention).*"),
     Regex("^(NetworkSecurityConfigProvider.install)"),
+    Regex("^(notifyContentCapture\\((?:true|false)\\))\\sfor\\s(.*)"),
     Regex("^(Open dex file)(?: from RAM)? ([\\w\\./]*)"),
     Regex("^(Open oat file)\\s+(.*)"),
     Regex("^(RegisterDexFile)\\s+(.*)"),
+    Regex("^($SLICE_NAME_REPORT_FULLY_DRAWN)\\s+(.*)"),
     Regex("^(serviceCreate):.*className=([\\w\\.]+)"),
     Regex("^(serviceStart):.*cmp=([\\w\\./]+)"),
     Regex("^(Setup proxies)"),
-    Regex("^(Start proc):\\s+(.*)"),
+    Regex("^($SLICE_NAME_PROC_START):\\s+(.*)"),
     Regex("^(SuspendThreadByThreadId) suspended (.+)$"),
     Regex("^(VerifyClass)(.*)"),
 
@@ -83,8 +88,68 @@ val SLICE_MAPPERS = arrayOf(
  * Class Definition
  */
 
-data class SliceInfo(val type: String, val payload: String?)
-data class StartupEndPoint(val timestamp: Double, val signal: String)
+data class SliceContents(val name: String, val value: String?)
+data class StartupEvent(val proc : ProcessModel,
+                        val name : String,
+                        val startTime : Double,
+                        val endTime : Double,
+                        val serverSideForkTime : Double,
+                        val reportFullyDrawnTime : Double?,
+                        val firstSliceTime : Double,
+                        val undifferentiatedTime : Double,
+                        val schedTimings : Map<SchedulingState, Double>,
+                        val allSlicesInfo : AggregateSliceInfoMap,
+                        val topLevelSliceInfo : AggregateSliceInfoMap,
+                        val undifferentiatedSliceInfo : AggregateSliceInfoMap,
+                        val nonNestedSliceInfo : AggregateSliceInfoMap)
+
+class AggregateSliceInfo {
+    var count : Int = 0
+    var totalTime : Double = 0.0
+
+    val values : MutableMap<String, Pair<Int, Double>> = mutableMapOf()
+}
+
+typealias MutableAggregateSliceInfoMap = MutableMap<String, AggregateSliceInfo>
+typealias AggregateSliceInfoMap = Map<String, AggregateSliceInfo>
+
+class MissingProcessInfoException(pid : Int) : Exception("Missing process info for PID $pid")
+
+class MissingProcessException : Exception {
+    constructor(name : String) {
+        Exception("Unable to find process: $name")
+    }
+
+    constructor(name : String, lowerBound : Double, upperBound : Double) {
+        Exception("Unable to find process: $name" +
+                  " (Bounds: [${lowerBound.secondValueToMillisecondString()}," +
+                  " ${upperBound.secondValueToMillisecondString()}]")
+    }
+}
+
+class MissingSliceException : Exception {
+    constructor(pid : Int, type : String, value : String?) {
+        Exception("Unable to find slice. PID = $pid, Type = $type" +
+                  (if (value == null) "" else ", Value = $value"))
+    }
+
+    constructor(pid : Int, type : String, value : String?, lowerBound : Double, upperBound : Double) {
+        Exception("Unable to find slice. PID = $pid, Type = $type" +
+                  (if (value == null) "" else ", Value = $value") +
+                  " (Bounds: [${lowerBound.secondValueToMillisecondString()}," +
+                  " ${upperBound.secondValueToMillisecondString()}])")
+    }
+
+    constructor (pid : Int, pattern : Regex) {
+        Exception("Unable to find slice.  PID = $pid, Pattern = $pattern")
+    }
+
+    constructor (pid : Int, pattern : Regex, lowerBound : Double, upperBound : Double) {
+        Exception("Unable to find slice.  PID = $pid, Pattern = $pattern" +
+                  " (Bounds: [${lowerBound.secondValueToMillisecondString()}," +
+                  " ${upperBound.secondValueToMillisecondString()}])")
+    }
+}
 
 /*
  * Class Extensions
@@ -92,62 +157,278 @@ data class StartupEndPoint(val timestamp: Double, val signal: String)
 
 fun Double.secondValueToMillisecondString() = "%.3f ms".format(this * 1000.0)
 
-fun Model.findIDsByName(query_name: String): Pair<Int, Int?>? {
+fun ProcessModel.fuzzyNameMatch(queryName : String) : Boolean {
+    if (queryName.endsWith(this.name)) {
+        return true
+    } else {
+        for (thread in this.threads) {
+            if (queryName.endsWith(thread.name)) {
+                return true
+            }
+        }
+    }
+
+    return false
+}
+
+fun Model.findProcess(queryName: String,
+                      lowerBound : Double = this.beginTimestamp,
+                      upperBound : Double = this.endTimestamp): ProcessModel {
+
     for (process in this.processes.values) {
-        if (query_name.endsWith(process.name)) {
-            return Pair(process.id, null)
+        if (process.fuzzyNameMatch(queryName)) {
+            val firstSliceStart =
+                process.
+                    threads.
+                    map { it.slices }.
+                    filter { it.isNotEmpty() }.
+                    map { it.first().startTime }.
+                    min() ?: throw MissingProcessInfoException(process.id)
 
-        } else {
-            for (thread in process.threads) {
-                if (query_name.endsWith(thread.name)) {
-                    return Pair(process.id, thread.id)
-                }
+            if (firstSliceStart in lowerBound..upperBound) {
+                return process
             }
         }
     }
 
-    return null
+    if (lowerBound == this.beginTimestamp && upperBound == this.endTimestamp) {
+        throw MissingProcessException(queryName)
+    } else {
+        throw MissingProcessException(queryName, lowerBound, upperBound)
+    }
 }
 
-// Find the time at which we've defined startup to have ended.
-fun Model.getStartupEndTime(mainThread: ThreadModel, startupStartTime: Double): StartupEndPoint {
-    var endTimeInfo: StartupEndPoint? = null
+fun Model.getStartupEvents() : List<StartupEvent> {
+    val systemServerProc = this.findProcess(PROC_NAME_SYSTEM_SERVER)
 
-    SliceQueries.traverseSlices(mainThread, object : SliceTraverser {
-        override fun beginSlice(slice: Slice): TraverseAction {
-            if (endTimeInfo == null &&
-                (slice.name.startsWith(SLICE_NAME_ACTIVITY_DESTROY) ||
-                    slice.name.startsWith(SLICE_NAME_ACTIVITY_PAUSE) ||
-                    slice.name.startsWith(SLICE_NAME_ACTIVITY_RESUME))) {
+    val startupEvents = mutableListOf<StartupEvent>()
 
-                endTimeInfo = StartupEndPoint(slice.endTime, slice.name)
+    systemServerProc.asyncSlices.forEach { systemServerSlice ->
+        if (systemServerSlice.name.startsWith(SLICE_NAME_APP_LAUNCH)) {
 
-                return TraverseAction.VISIT_CHILDREN
-            } else if (slice.name.startsWith(SLICE_NAME_REPORT_FULLY_DRAWN)) {
-                endTimeInfo = StartupEndPoint(slice.endTime, slice.name)
+            val newProcName    = systemServerSlice.name.split(':', limit = 2)[1].trim()
+            val newProc        = this.findProcess(newProcName, systemServerSlice.startTime, systemServerSlice.endTime)
+            val startProcSlice = systemServerProc.findFirstSlice(SLICE_NAME_PROC_START, newProcName, systemServerSlice.startTime, systemServerSlice.endTime)
+            val rfdSlice       = systemServerProc.findFirstSliceOrNull(SLICE_NAME_REPORT_FULLY_DRAWN, newProcName, systemServerSlice.startTime)
+            val firstSliceTime = newProc.threads.map { it.slices.first().startTime }.min()!!
 
-                return TraverseAction.DONE
-            } else {
-                return TraverseAction.VISIT_CHILDREN
+            val schedSliceInfo : MutableMap<SchedulingState, Double> = mutableMapOf()
+            newProc.threads.first().schedSlices.forEach schedLoop@ { schedSlice ->
+                val origVal = schedSliceInfo.getOrDefault(schedSlice.state, 0.0)
+
+                when {
+                    schedSlice.startTime >= systemServerSlice.endTime -> return@schedLoop
+                    schedSlice.endTime <= systemServerSlice.endTime   -> schedSliceInfo[schedSlice.state] = origVal + schedSlice.duration
+                    else                                              -> {
+                        schedSliceInfo[schedSlice.state] = origVal + (systemServerSlice.endTime - schedSlice.startTime)
+                        return@schedLoop
+                    }
+                }
             }
+
+            var undifferentiatedTime = 0.0
+
+            val allSlicesInfo : MutableAggregateSliceInfoMap = mutableMapOf()
+            val topLevelSliceInfo : MutableAggregateSliceInfoMap = mutableMapOf()
+            val undifferentiatedSliceInfo : MutableAggregateSliceInfoMap = mutableMapOf()
+            val nonNestedSliceInfo : MutableAggregateSliceInfoMap = mutableMapOf()
+
+            SliceQueries.traverseSlices(newProc.threads.first(), object : SliceTraverser {
+                // Our depth down an individual tree in the slice forest.
+                var treeDepth = -1
+                val sliceDepths: MutableMap<String, Int> = mutableMapOf()
+
+                var lastTopLevelSlice : Slice? = null
+
+                override fun beginSlice(slice : Slice) : TraverseAction {
+                    val sliceContents = parseSliceName(slice.name)
+
+                    ++this.treeDepth
+
+                    val sliceDepth = this.sliceDepths.getOrDefault(sliceContents.name, -1)
+                    this.sliceDepths[sliceContents.name] = sliceDepth + 1
+
+                    if (slice.startTime < systemServerSlice.endTime) {
+                        // This slice starts during the startup period.  If it
+                        // ends within the startup period we will record info
+                        // from this slice.  Either way we will visit its
+                        // children.
+
+                        if (this.treeDepth == 0 && this.lastTopLevelSlice != null) {
+                            undifferentiatedTime += (slice.startTime - this.lastTopLevelSlice!!.endTime)
+                        }
+
+                        if (slice.endTime <= systemServerSlice.endTime) {
+                            // This slice belongs in our collection.
+
+                            // All Slice Timings
+                            aggregateSliceInfo(allSlicesInfo, sliceContents, slice.duration)
+
+                            // Undifferentiated Timings
+                            aggregateSliceInfo(undifferentiatedSliceInfo, sliceContents, slice.durationSelf)
+
+                            // Top-level timings
+                            if (this.treeDepth == 0) {
+                                aggregateSliceInfo(topLevelSliceInfo, sliceContents, slice.duration)
+                            }
+
+                            // Non-nested timings
+                            if (sliceDepths[sliceContents.name] == 0) {
+                                aggregateSliceInfo(nonNestedSliceInfo, sliceContents, slice.duration)
+                            }
+                        }
+
+                        return TraverseAction.VISIT_CHILDREN
+
+                    } else {
+                        // All contents of this slice occur after the startup
+                        // period has ended. We don't need to record anything
+                        // or traverse any children.
+                        return TraverseAction.DONE
+                    }
+                }
+
+                override fun endSlice(slice : Slice) {
+                    if (this.treeDepth == 0) {
+                        lastTopLevelSlice = slice
+                    }
+
+                    val sliceInfo = parseSliceName(slice.name)
+                    this.sliceDepths[sliceInfo.name] = this.sliceDepths[sliceInfo.name]!! - 1
+
+                    --this.treeDepth
+                }
+            })
+
+            startupEvents.add(StartupEvent(newProc,
+                                           newProcName,
+                                           systemServerSlice.startTime,
+                                           systemServerSlice.endTime,
+                                           startProcSlice.duration,
+                                           rfdSlice?.startTime,
+                                           firstSliceTime,
+                                           undifferentiatedTime,
+                                           schedSliceInfo,
+                                           allSlicesInfo,
+                                           topLevelSliceInfo,
+                                           undifferentiatedSliceInfo,
+                                           nonNestedSliceInfo))
         }
-    })
+    }
 
-    return endTimeInfo
-        ?: StartupEndPoint(min(startupStartTime + DEFAULT_START_DURATION, this.endTimestamp), "DefaultDuration")
+    return startupEvents
+}
+
+fun aggregateSliceInfo(infoMap : MutableAggregateSliceInfoMap, sliceContents : SliceContents, duration : Double) {
+    val aggInfo = infoMap.getOrPut(sliceContents.name, ::AggregateSliceInfo)
+    ++aggInfo.count
+    aggInfo.totalTime += duration
+    if (sliceContents.value != null) {
+        val (uniqueValueCount, uniqueValueDuration) = aggInfo.values.getOrDefault(sliceContents.value, Pair(0, 0.0))
+        aggInfo.values[sliceContents.value] = Pair(uniqueValueCount + 1, uniqueValueDuration + duration)
+    }
+}
+
+// TODO: Move into SliceQueries
+fun ProcessModel.findFirstSlice(queryType : String,
+                                queryValue : String?,
+                                lowerBound : Double = this.model.beginTimestamp,
+                                upperBound : Double = this.model.endTimestamp) : Slice {
+
+    val foundSlice = this.findFirstSliceOrNull(queryType, queryValue, lowerBound, upperBound)
+
+    if (foundSlice != null) {
+        return foundSlice
+    } else if (lowerBound == this.model.beginTimestamp && upperBound == this.model.endTimestamp) {
+        throw MissingSliceException(this.id, queryType, queryValue)
+    } else {
+        throw MissingSliceException(this.id, queryType, queryValue, lowerBound, upperBound)
+    }
+}
+
+// TODO: Move into SliceQueries
+fun ProcessModel.findFirstSlice(pattern : Regex,
+                                lowerBound : Double = this.model.beginTimestamp,
+                                upperBound : Double = this.model.endTimestamp) : Slice {
+
+    val foundSlice = this.findFirstSliceOrNull(pattern, lowerBound, upperBound)
+
+    if (foundSlice != null) {
+        return foundSlice
+    } else if (lowerBound == this.model.beginTimestamp && upperBound == this.model.endTimestamp) {
+        throw MissingSliceException(this.id, pattern)
+    } else {
+        throw MissingSliceException(this.id, pattern, lowerBound, upperBound)
+    }
+}
+
+// TODO: Move into SliceQueries
+fun ProcessModel.findFirstSliceOrNull(queryType : String,
+                                queryValue : String?,
+                                lowerBound : Double = this.model.beginTimestamp,
+                                upperBound : Double = this.model.endTimestamp) : Slice? {
+
+    return SliceQueries.selectFirst(this) { slice ->
+        val sliceInfo = parseSliceName(slice.name)
+
+        sliceInfo.name == queryType &&
+            (queryValue == null || sliceInfo.value == queryValue) &&
+        lowerBound <= slice.startTime &&
+        slice.startTime <= upperBound
+    }
+}
+
+// TODO: Move into SliceQueries
+fun ProcessModel.findFirstSliceOrNull(pattern : Regex,
+                                lowerBound : Double = this.model.beginTimestamp,
+                                upperBound : Double = this.model.endTimestamp) : Slice? {
+
+    return SliceQueries.selectFirst(this) { slice ->
+        pattern.find(slice.name) != null &&
+            lowerBound <= slice.startTime &&
+            slice.startTime <= upperBound
+    }
+}
+
+// TODO: Move into SliceQueries
+fun ProcessModel.findAllSlices(queryType : String,
+                               queryValue : String?,
+                               lowerBound : Double = this.model.beginTimestamp,
+                               upperBound : Double = this.model.endTimestamp) : List<Slice> {
+
+    return SliceQueries.selectAll(this) { slice ->
+        val sliceInfo = parseSliceName(slice.name)
+
+        sliceInfo.name == queryType &&
+                (queryValue == null || sliceInfo.value == queryValue) &&
+        lowerBound <= slice.startTime &&
+        slice.startTime <= upperBound
+    }
+}
+
+// TODO: Move into SliceQueries
+fun ProcessModel.findAllSlices(pattern : Regex,
+                               lowerBound : Double = this.model.beginTimestamp,
+                               upperBound : Double = this.model.endTimestamp) : List<Slice> {
+
+    return SliceQueries.selectAll(this) { slice ->
+        pattern.find(slice.name) != null &&
+            lowerBound <= slice.startTime &&
+            slice.startTime <= upperBound
+    }
 }
 
 /*
  * Functions
  */
 
-fun parseSliceInfo(sliceString: String): SliceInfo {
+fun parseSliceName(sliceString: String): SliceContents {
     when {
     // Handle special cases.
-        sliceString == SLICE_NAME_OPEN_DEX_FILE_FUNCTION -> return SliceInfo("Open dex file function invocation", null)
-        sliceString.startsWith(SLICE_NAME_ALTERNATE_DEX_OPEN_START) -> return SliceInfo("Open dex file", sliceString.split(" ").last().trim())
-        sliceString.startsWith(SLICE_NAME_OBFUSCATED_TRACE_START) -> return SliceInfo("Obfuscated trace point", null)
-        sliceString[0] == '/' -> return SliceInfo("Load Dex files from classpath", null)
+        sliceString == SLICE_NAME_OPEN_DEX_FILE_FUNCTION -> return SliceContents("Open dex file function invocation", null)
+        sliceString.startsWith(SLICE_NAME_ALTERNATE_DEX_OPEN_START) -> return SliceContents("Open dex file", sliceString.split(" ").last().trim())
+        sliceString.startsWith(SLICE_NAME_OBFUSCATED_TRACE_START) -> return SliceContents("Obfuscated trace point", null)
+        sliceString[0] == '/' -> return SliceContents("Load Dex files from classpath", null)
 
         else -> {
             // Search the slice mapping patterns.
@@ -164,12 +445,12 @@ fun parseSliceInfo(sliceString: String): SliceInfo {
                             null
                         }
 
-                    return SliceInfo(sliceType, sliceDetails)
+                    return SliceContents(sliceType, sliceDetails)
                 }
             }
 
-            return SliceInfo("Unknown Slice", sliceString)
+            return SliceContents("Unknown Slice", sliceString)
         }
     }
 
-}
\ No newline at end of file
+}
diff --git a/trebuchet/startup-summarizer/src/StartupSummarizer.kt b/trebuchet/startup-summarizer/src/StartupSummarizer.kt
index 0a37460..616a87f 100644
--- a/trebuchet/startup-summarizer/src/StartupSummarizer.kt
+++ b/trebuchet/startup-summarizer/src/StartupSummarizer.kt
@@ -26,12 +26,8 @@
  */
 
 import java.io.File
-import trebuchet.model.Model
 import trebuchet.extras.parseTrace
-import trebuchet.model.base.Slice
-import trebuchet.queries.SliceQueries
-import trebuchet.queries.SliceTraverser
-import trebuchet.queries.TraverseAction
+import trebuchet.model.SchedulingState
 import kotlin.math.pow
 import kotlin.math.sqrt
 import kotlin.system.exitProcess
@@ -71,15 +67,8 @@ enum class Temperature {
     WARM
 }
 
-data class StartupRecord(val appName : String,
-                         val startupTime : Double,
-                         val timeToFirstSlice : Double,
-                         val topLevelTimings : MutableMap<String, Double> = mutableMapOf(),
-                         val nonNestedTimings : MutableMap<String, Double> = mutableMapOf(),
-                         val undifferentiatedTimings : MutableMap<String, Double> = mutableMapOf())
-
-class CompilerRecord(val cold : MutableList<StartupRecord> = mutableListOf(),
-                     val warm : MutableList<StartupRecord> = mutableListOf()) {
+class CompilerRecord(val cold : MutableList<StartupEvent> = mutableListOf(),
+                     val warm : MutableList<StartupEvent> = mutableListOf()) {
 
     fun numSamples() : Int {
         return this.cold.size + this.warm.size
@@ -95,8 +84,6 @@ class ApplicationRecord(val quicken : CompilerRecord = CompilerRecord(),
     }
 }
 
-class SystemServerException: Exception("Unable to locate system server")
-
 /*
  * Class Extensions
  */
@@ -105,7 +92,7 @@ class SystemServerException: Exception("Unable to locate system server")
  * Helper Functions
  */
 
-fun addStartupRecord(records : MutableMap<String, ApplicationRecord>, record : StartupRecord, appName : String, compiler : CompilerFilter, temperature : Temperature) {
+fun addStartupRecord(records : MutableMap<String, ApplicationRecord>, startupEvent : StartupEvent, appName : String, compiler : CompilerFilter, temperature : Temperature) {
     val applicationRecord = records.getOrPut(appName) { ApplicationRecord() }
 
     val compilerRecord =
@@ -118,7 +105,7 @@ fun addStartupRecord(records : MutableMap<String, ApplicationRecord>, record : S
     when (temperature) {
         Temperature.COLD -> compilerRecord.cold
         Temperature.WARM -> compilerRecord.warm
-    }.add(record)
+    }.add(startupEvent)
 }
 
 fun averageAndStandardDeviation(values : List<Double>) : Pair<Double, Double> {
@@ -134,114 +121,6 @@ fun averageAndStandardDeviation(values : List<Double>) : Pair<Double, Double> {
     return Pair(averageValue, sqrt(sumOfSquaredDiffs / values.size))
 }
 
-fun extractStartupRecords(model : Model) : List<StartupRecord> {
-    val records : MutableList<StartupRecord> = mutableListOf()
-
-    // TODO: Use unified reporting mechanism when it is implemented.
-    val systemServerIDs = model.findIDsByName(PROC_NAME_SYSTEM_SERVER) ?: throw SystemServerException()
-
-    val systemServerProc = model.processes[systemServerIDs.first]
-    val startedApps: MutableMap<Int, Pair<String, Double>> = mutableMapOf()
-
-    systemServerProc!!.threads.forEach { thread ->
-        SliceQueries.iterSlices(thread) { slice ->
-            if (slice.name.startsWith(SLICE_NAME_PROC_START)) {
-
-                val newProcName = slice.name.split(':', limit = 2)[1].trim()
-                val newProcIDs = model.findIDsByName(newProcName)
-
-                if (newProcIDs != null && !startedApps.containsKey(newProcIDs.first)) {
-                    startedApps[newProcIDs.first] = Pair(newProcName, slice.startTime)
-                }
-
-                // TODO: Use unified reporting mechanism when it is implemented.
-//                when {
-//                    newProcIDs == null -> println("\tUnable to find PID for process `$newProcName`")
-//                    startedApps.containsKey(newProcIDs.first) -> println("\tPID already mapped to started app")
-//                    else -> startedApps[newProcIDs.first] = Pair(newProcName, slice.startTime)
-//                }
-            }
-        }
-    }
-
-    startedApps.forEach { pid, (startedName, startupStartTime) ->
-        val process = model.processes[pid]
-        val mainThread = process!!.threads[0]
-
-        val startupEndTime = model.getStartupEndTime(mainThread, startupStartTime)
-
-        // Processes with end points defined by the default duration are currently noise.
-        if (startupEndTime.signal != "DefaultDuration") {
-
-            val newRecord = StartupRecord(startedName,
-                startupEndTime.timestamp - startupStartTime,
-                mainThread.slices.first().startTime - startupStartTime)
-
-            SliceQueries.traverseSlices(mainThread, object : SliceTraverser {
-                // Our depth down an individual tree in the slice forest.
-                var treeDepth = -1
-
-                val sliceDepths: MutableMap<String, Int> = mutableMapOf()
-
-                override fun beginSlice(slice: Slice): TraverseAction {
-                    val sliceInfo = parseSliceInfo(slice.name)
-
-                    ++this.treeDepth
-
-                    val sliceDepth = this.sliceDepths.getOrDefault(sliceInfo.type, -1)
-                    this.sliceDepths[sliceInfo.type] = sliceDepth + 1
-
-                    if (slice.startTime < startupEndTime.timestamp) {
-                        // This slice starts during the startup period.  If it
-                        // ends within the startup period we will record info
-                        // from this slice.  Either way we will visit its
-                        // children.
-
-                        if (slice.endTime <= startupEndTime.timestamp) {
-                            // Top-level timing
-                            if (this.treeDepth == 0) {
-                                val oldValue = newRecord.topLevelTimings.getOrDefault(sliceInfo.type, 0.0)
-                                newRecord.topLevelTimings[sliceInfo.type] = oldValue + slice.duration
-                            }
-
-                            if (INTERESTING_SLICES.contains(sliceInfo.type)) {
-                                // Undifferentiated timing
-                                var oldValue = newRecord.undifferentiatedTimings.getOrDefault(sliceInfo.type, 0.0)
-                                newRecord.undifferentiatedTimings[sliceInfo.type] = oldValue + slice.durationSelf
-
-                                // Non-nested timing
-                                if (sliceDepths[sliceInfo.type] == 0) {
-                                    oldValue = newRecord.nonNestedTimings.getOrDefault(sliceInfo.type, 0.0)
-                                    newRecord.nonNestedTimings[sliceInfo.type] = oldValue + slice.duration
-                                }
-                            }
-                        }
-
-                        return TraverseAction.VISIT_CHILDREN
-
-                    } else {
-                        // All contents of this slice occur after the startup
-                        // period has ended. We don't need to record anything
-                        // or traverse any children.
-                        return TraverseAction.DONE
-                    }
-                }
-
-                override fun endSlice(slice: Slice) {
-                    val sliceInfo = parseSliceInfo(slice.name)
-
-                    --this.treeDepth
-                    this.sliceDepths[sliceInfo.type] = this.sliceDepths[sliceInfo.type]!! - 1
-                }
-            })
-
-            records.add(newRecord)
-        }
-    }
-
-    return records
-}
-
 fun parseFileName(fileName : String) : Triple<String, CompilerFilter, Temperature> {
     val md = FILENAME_PATTERN.find(fileName)
 
@@ -299,35 +178,63 @@ fun printCompilerRecord(record : CompilerRecord) {
     }
 }
 
-fun printSampleSet(records : List<StartupRecord>) {
+fun printSampleSet(records : List<StartupEvent>) {
 
-    val (startupTimeAverage, startupTimeStandardDeviation) = averageAndStandardDeviation(records.map {it.startupTime})
-    val (timeToFirstSliceAverage, timeToFirstSliceStandardDeviation) = averageAndStandardDeviation(records.map {it.timeToFirstSlice})
+    val (startupTimeAverage, startupTimeStandardDeviation) = averageAndStandardDeviation(records.map {it.endTime - it.startTime})
+    val (timeToFirstSliceAverage, timeToFirstSliceStandardDeviation) = averageAndStandardDeviation(records.map {it.firstSliceTime - it.startTime})
+    val (undifferentiatedTimeAverage, undifferentiatedTimeStandardDeviation) = averageAndStandardDeviation(records.map {it.undifferentiatedTime})
 
     println("\t\t\tAverage startup time:            ${startupTimeAverage.secondValueToMillisecondString()}")
     println("\t\t\tStartup time standard deviation: ${startupTimeStandardDeviation.secondValueToMillisecondString()}")
     println("\t\t\tAverage time to first slice:     ${timeToFirstSliceAverage.secondValueToMillisecondString()}")
     println("\t\t\tTTFS standard deviation:         ${timeToFirstSliceStandardDeviation.secondValueToMillisecondString()}")
+    println("\t\t\tAverage undifferentiated time:   ${undifferentiatedTimeAverage.secondValueToMillisecondString()}")
+    println("\t\t\tUDT standard deviation:          ${undifferentiatedTimeStandardDeviation.secondValueToMillisecondString()}")
+
+    if (records.first().reportFullyDrawnTime != null) {
+        val (rfdTimeAverage, rfdTimeStandardDeviation) = averageAndStandardDeviation(records.map { it.reportFullyDrawnTime!! - it.startTime})
+        println("\t\t\tAverage RFD time:                ${rfdTimeAverage.secondValueToMillisecondString()}")
+        println("\t\t\tRFD time standard deviation:     ${rfdTimeStandardDeviation.secondValueToMillisecondString()}")
+    }
+
+    println()
+
+    println("\t\t\tScheduling info:")
+    SchedulingState.values().toSortedSet().forEach { schedState ->
+        val (schedStateTimeAverage, schedStateTimeStandardDeviation) = averageAndStandardDeviation(records.map {it.schedTimings.getOrDefault(schedState, 0.0)})
+
+        if (schedStateTimeAverage != 0.0) {
+            println(
+                "\t\t\t\t${schedState.friendlyName}: ${schedStateTimeAverage.secondValueToMillisecondString()} / ${schedStateTimeStandardDeviation.secondValueToMillisecondString()}")
+        }
+    }
+
     println()
 
     // Definition of printing helper.
-    fun printTimings(timingMaps : List<Map<String, Double>>) {
+    fun printSliceTimings(sliceInfos : List<AggregateSliceInfoMap>, filterSlices : Boolean) {
         val samples : MutableMap<String, MutableList<Double>> = mutableMapOf()
 
-        timingMaps.forEach { timingMap ->
-            timingMap.forEach {sliceType, duration ->
-                samples.getOrPut(sliceType) { mutableListOf() }.add(duration)
+        sliceInfos.forEach { sliceInfo ->
+            sliceInfo.forEach {sliceName, aggInfo ->
+                samples.getOrPut(sliceName, ::mutableListOf).add(aggInfo.totalTime)
             }
         }
 
-        samples.forEach {sliceType, sliceSamples ->
-            val (sliceDurationAverage, sliceDurationStandardDeviation) = averageAndStandardDeviation(sliceSamples)
+        samples.forEach {sliceName, sliceSamples ->
+            if (!filterSlices || INTERESTING_SLICES.contains(sliceName)) {
+                val (sliceDurationAverage, sliceDurationStandardDeviation) = averageAndStandardDeviation(
+                    sliceSamples)
 
-            println("\t\t\t\t$sliceType:")
+                println("\t\t\t\t$sliceName:")
 
-            println("\t\t\t\t\tAverage duration:     ${sliceDurationAverage.secondValueToMillisecondString()}")
-            println("\t\t\t\t\tStandard deviation:   ${sliceDurationStandardDeviation.secondValueToMillisecondString()}")
-            println("\t\t\t\t\tStartup time percent: %.2f%%".format((sliceDurationAverage / startupTimeAverage) * 100))
+                println(
+                    "\t\t\t\t\tAverage duration:     ${sliceDurationAverage.secondValueToMillisecondString()}")
+                println(
+                    "\t\t\t\t\tStandard deviation:   ${sliceDurationStandardDeviation.secondValueToMillisecondString()}")
+                println("\t\t\t\t\tStartup time percent: %.2f%%".format(
+                    (sliceDurationAverage / startupTimeAverage) * 100))
+            }
         }
     }
 
@@ -336,16 +243,26 @@ fun printSampleSet(records : List<StartupRecord>) {
      */
 
     println("\t\t\tTop-level timings:")
-    printTimings(records.map {it.topLevelTimings})
+    printSliceTimings(records.map {it.topLevelSliceInfo}, false)
     println()
     println("\t\t\tNon-nested timings:")
-    printTimings(records.map {it.nonNestedTimings})
+    printSliceTimings(records.map {it.nonNestedSliceInfo}, true)
     println()
     println("\t\t\tUndifferentiated timing:")
-    printTimings(records.map {it.undifferentiatedTimings})
+    printSliceTimings(records.map {it.undifferentiatedSliceInfo}, true)
     println()
 }
 
+fun printPlainText(records : MutableMap<String, ApplicationRecord>) {
+    records.forEach { appName, record ->
+        if (record.numSamples() > SAMPLE_THRESHOLD_APPLICATION) {
+            println("$appName:")
+            printAppRecord(record)
+            println()
+        }
+    }
+}
+
 /*
  * Main Function
  */
@@ -357,6 +274,7 @@ fun main(args: Array<String>) {
     }
 
     val records : MutableMap<String, ApplicationRecord> = mutableMapOf()
+    val exceptions : MutableList<Pair<String, Exception>> = mutableListOf()
 
     var processedFiles = 0
     var erroredFiles = 0
@@ -367,30 +285,31 @@ fun main(args: Array<String>) {
         val trace = parseTrace(File(fileName), false)
 
         try {
-            val traceRecords : List<StartupRecord> = extractStartupRecords(trace)
-
-            ++processedFiles
-
-            print("\rProgress: $processedFiles ($erroredFiles) / ${args.size}")
+            val traceStartupEvents : List<StartupEvent> = trace.getStartupEvents()
 
-            traceRecords.forEach { startupRecord ->
-                addStartupRecord(records, startupRecord, startupRecord.appName, compiler, temperature)
+            traceStartupEvents.forEach { startupEvent ->
+                addStartupRecord(records, startupEvent, startupEvent.name, compiler,
+                                 temperature)
             }
 
-        } catch (e: SystemServerException) {
-            ++processedFiles
+        } catch (e: Exception) {
+            exceptions.add(Pair(fileName, e))
             ++erroredFiles
+        } finally {
+            ++processedFiles
+
             print("\rProgress: $processedFiles ($erroredFiles) / ${args.size}")
         }
     }
 
     println()
 
-    records.forEach { appName, record ->
-        if (record.numSamples() > SAMPLE_THRESHOLD_APPLICATION) {
-            println("$appName:")
-            printAppRecord(record)
-            println()
+    printPlainText(records)
+
+    if (exceptions.count() > 0) {
+        println("Exceptions:")
+        exceptions.forEach { (fileName, exception) ->
+            println("\t$fileName: $exception${if (exception.message != null) "(${exception.message})" else ""}")
         }
     }
 }
\ No newline at end of file