1 /*
<lambda>null2  * Copyright 2018 Google Inc.
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *     https://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 /*
18  * Notes
19  *
20  * TODO (chriswailes): Build a unified error reporting mechanism.
21  * TODO (chriswailes): Support CSV output
22  */
23 
24 /*
25  * Imports
26  */
27 
28 import java.io.File
29 
30 import kotlin.math.pow
31 import kotlin.math.sqrt
32 import kotlin.system.exitProcess
33 
34 import trebuchet.extras.parseTrace
35 import trebuchet.model.SchedulingState
36 import trebuchet.util.slices.*
37 import trebuchet.util.time.*
38 
39 /*
40  * Constants
41  */
42 
43 val FILENAME_PATTERN = Regex("launch-(\\w+)-(\\w+)-(quicken|speed|speed-profile)-(cold|warm)-\\d")
44 
45 val INTERESTING_SLICES = arrayOf(
46     SLICE_NAME_ACTIVITY_START,
47     SLICE_NAME_ACTIVITY_THREAD_MAIN,
48     SLICE_NAME_APP_IMAGE_INTERN_STRING,
49     SLICE_NAME_APP_IMAGE_LOADING,
50     SLICE_NAME_BIND_APPLICATION,
51     SLICE_NAME_INFLATE,
52     SLICE_NAME_POST_FORK,
53     SLICE_NAME_ZYGOTE_INIT)
54 
55 const val SAMPLE_THRESHOLD_APPLICATION = 5
56 const val SAMPLE_THRESHOLD_COMPILER = 5
57 const val SAMPLE_THRESHOLD_TEMPERATURE = 5
58 
59 /*
60  * Class Definition
61  */
62 
63 enum class CompilerFilter {
64     QUICKEN,
65     SPEED,
66     SPEED_PROFILE
67 }
68 
69 enum class Temperature {
70     COLD,
71     WARM
72 }
73 
74 class CompilerRecord(val cold : MutableList<StartupEvent> = mutableListOf(),
75                      val warm : MutableList<StartupEvent> = mutableListOf()) {
76 
numSamplesnull77     fun numSamples() : Int {
78         return this.cold.size + this.warm.size
79     }
80 }
81 
82 class ApplicationRecord(val quicken : CompilerRecord = CompilerRecord(),
83                         val speed : CompilerRecord = CompilerRecord(),
84                         val speedProfile : CompilerRecord = CompilerRecord()) {
85 
numSamplesnull86     fun numSamples() : Int {
87         return this.quicken.numSamples() + this.speed.numSamples() + this.speedProfile.numSamples()
88     }
89 }
90 
91 /*
92  * Class Extensions
93  */
94 
95 /*
96  * Helper Functions
97  */
98 
addStartupRecordnull99 fun addStartupRecord(records : MutableMap<String, ApplicationRecord>, startupEvent : StartupEvent, appName : String, compiler : CompilerFilter, temperature : Temperature) {
100     val applicationRecord = records.getOrPut(appName) { ApplicationRecord() }
101 
102     val compilerRecord =
103         when (compiler) {
104             CompilerFilter.QUICKEN -> applicationRecord.quicken
105             CompilerFilter.SPEED -> applicationRecord.speed
106             CompilerFilter.SPEED_PROFILE -> applicationRecord.speedProfile
107         }
108 
109     when (temperature) {
110         Temperature.COLD -> compilerRecord.cold
111         Temperature.WARM -> compilerRecord.warm
112     }.add(startupEvent)
113 }
114 
averageAndStandardDeviationnull115 fun averageAndStandardDeviation(values : List<Double>) : Pair<Double, Double> {
116     val total = values.sum()
117     val averageValue = total / values.size
118 
119     var sumOfSquaredDiffs = 0.0
120 
121     values.forEach { value ->
122         sumOfSquaredDiffs += (value - averageValue).pow(2)
123     }
124 
125     return Pair(averageValue, sqrt(sumOfSquaredDiffs / values.size))
126 }
127 
parseFileNamenull128 fun parseFileName(fileName : String) : Triple<String, CompilerFilter, Temperature> {
129     val md = FILENAME_PATTERN.find(fileName)
130 
131     if (md != null) {
132         val compilerFilter =
133             when (md.groups[3]!!.value) {
134                 "quicken" -> CompilerFilter.QUICKEN
135                 "speed" -> CompilerFilter.SPEED
136                 "speed-profile" -> CompilerFilter.SPEED_PROFILE
137                 else -> throw Exception("Bad compiler match data.")
138             }
139 
140         val temperature =
141             when (md.groups[4]!!.value) {
142                 "cold" -> Temperature.COLD
143                 "warm" -> Temperature.WARM
144                 else -> throw Exception("Bad temperature match data.")
145             }
146 
147         return Triple(md.groups[1]!!.value, compilerFilter, temperature)
148     } else {
149         println("Unrecognized file name: $fileName")
150         exitProcess(1)
151     }
152 }
153 
printPlainTextnull154 fun printPlainText(records : MutableMap<String, ApplicationRecord>) {
155     records.forEach { appName, record ->
156         if (record.numSamples() > SAMPLE_THRESHOLD_APPLICATION) {
157             println("$appName:")
158             printAppRecordPlainText(record)
159             println()
160         }
161     }
162 }
163 
printAppRecordPlainTextnull164 fun printAppRecordPlainText(record : ApplicationRecord) {
165     if (record.quicken.numSamples() > SAMPLE_THRESHOLD_COMPILER) {
166         println("\tQuicken:")
167         printCompilerRecordPlainText(record.quicken)
168     }
169 
170     if (record.speed.numSamples() > SAMPLE_THRESHOLD_COMPILER) {
171         println("\tSpeed:")
172         printCompilerRecordPlainText(record.speed)
173     }
174 
175     if (record.speedProfile.numSamples() > SAMPLE_THRESHOLD_COMPILER) {
176         println("\tSpeed Profile:")
177         printCompilerRecordPlainText(record.speedProfile)
178     }
179 }
180 
printCompilerRecordPlainTextnull181 fun printCompilerRecordPlainText(record : CompilerRecord) {
182     if (record.cold.size > SAMPLE_THRESHOLD_TEMPERATURE) {
183         println("\t\tCold:")
184         printSampleSetPlainText(record.cold)
185     }
186 
187     if (record.warm.size > SAMPLE_THRESHOLD_TEMPERATURE) {
188         println("\t\tWarm:")
189         printSampleSetPlainText(record.warm)
190     }
191 }
192 
printSampleSetPlainTextnull193 fun printSampleSetPlainText(records : List<StartupEvent>) {
194 
195     val (startupTimeAverage, startupTimeStandardDeviation) = averageAndStandardDeviation(records.map {it.endTime - it.startTime})
196     val (timeToFirstSliceAverage, timeToFirstSliceStandardDeviation) = averageAndStandardDeviation(records.map {it.firstSliceTime - it.startTime})
197     val (undifferentiatedTimeAverage, undifferentiatedTimeStandardDeviation) = averageAndStandardDeviation(records.map {it.undifferentiatedTime})
198 
199     println("\t\t\tAverage startup time:            ${startupTimeAverage.secondValueToMillisecondString()}")
200     println("\t\t\tStartup time standard deviation: ${startupTimeStandardDeviation.secondValueToMillisecondString()}")
201     println("\t\t\tAverage time to first slice:     ${timeToFirstSliceAverage.secondValueToMillisecondString()}")
202     println("\t\t\tTTFS standard deviation:         ${timeToFirstSliceStandardDeviation.secondValueToMillisecondString()}")
203     println("\t\t\tAverage undifferentiated time:   ${undifferentiatedTimeAverage.secondValueToMillisecondString()}")
204     println("\t\t\tUDT standard deviation:          ${undifferentiatedTimeStandardDeviation.secondValueToMillisecondString()}")
205 
206     if (records.first().reportFullyDrawnTime != null) {
207         val (rfdTimeAverage, rfdTimeStandardDeviation) = averageAndStandardDeviation(records.map { it.reportFullyDrawnTime!! - it.startTime})
208         println("\t\t\tAverage RFD time:                ${rfdTimeAverage.secondValueToMillisecondString()}")
209         println("\t\t\tRFD time standard deviation:     ${rfdTimeStandardDeviation.secondValueToMillisecondString()}")
210     }
211 
212     println()
213 
214     println("\t\t\tScheduling info:")
215     SchedulingState.values().toSortedSet().forEach { schedState ->
216         val (schedStateTimeAverage, schedStateTimeStandardDeviation) = averageAndStandardDeviation(records.map {it.schedTimings.getOrDefault(schedState, 0.0)})
217 
218         if (schedStateTimeAverage != 0.0) {
219             println(
220                 "\t\t\t\t${schedState.friendlyName}: ${schedStateTimeAverage.secondValueToMillisecondString()} / ${schedStateTimeStandardDeviation.secondValueToMillisecondString()}")
221         }
222     }
223 
224     println()
225 
226     // Definition of printing helper.
227     fun printSliceTimings(sliceInfos : List<AggregateSliceInfoMap>, filterSlices : Boolean) {
228         val samples : MutableMap<String, MutableList<Double>> = mutableMapOf()
229 
230         sliceInfos.forEach { sliceInfo ->
231             sliceInfo.forEach {sliceName, aggInfo ->
232                 samples.getOrPut(sliceName, ::mutableListOf).add(aggInfo.totalTime)
233             }
234         }
235 
236         samples.forEach {sliceName, sliceSamples ->
237             if (!filterSlices || INTERESTING_SLICES.contains(sliceName)) {
238                 val (sliceDurationAverage, sliceDurationStandardDeviation) = averageAndStandardDeviation(
239                     sliceSamples)
240 
241                 println("\t\t\t\t$sliceName:")
242 
243                 println(
244                     "\t\t\t\t\tAverage duration:     ${sliceDurationAverage.secondValueToMillisecondString()}")
245                 println(
246                     "\t\t\t\t\tStandard deviation:   ${sliceDurationStandardDeviation.secondValueToMillisecondString()}")
247                 println("\t\t\t\t\tStartup time percent: %.2f%%".format(
248                     (sliceDurationAverage / startupTimeAverage) * 100))
249             }
250         }
251     }
252 
253     /*
254      * Timing accumulation
255      */
256 
257     println("\t\t\tTop-level timings:")
258     printSliceTimings(records.map {it.topLevelSliceInfo}, false)
259     println()
260     println("\t\t\tNon-nested timings:")
261     printSliceTimings(records.map {it.nonNestedSliceInfo}, true)
262     println()
263     println("\t\t\tUndifferentiated timing:")
264     printSliceTimings(records.map {it.undifferentiatedSliceInfo}, true)
265     println()
266 }
267 
printCSVnull268 fun printCSV(records : MutableMap<String, ApplicationRecord>) {
269     println("Application Name, Compiler Filter, Temperature, Startup Time Avg (ms), Startup Time SD (ms), Time-to-first-slice Avg (ms), Time-to-first-slice SD (ms), Report Fully Drawn Avg (ms), Report Fully Drawn SD (ms)")
270 
271     records.forEach { appName, record ->
272         if (record.numSamples() > SAMPLE_THRESHOLD_APPLICATION) {
273             printAppRecordCSV(appName, record)
274         }
275     }
276 }
277 
printAppRecordCSVnull278 fun printAppRecordCSV(appName : String, record : ApplicationRecord) {
279     if (record.quicken.numSamples() > SAMPLE_THRESHOLD_COMPILER) {
280         printCompilerRecordCSV(appName, "quicken", record.quicken)
281     }
282 
283     if (record.speed.numSamples() > SAMPLE_THRESHOLD_COMPILER) {
284         printCompilerRecordCSV(appName, "speed", record.speed)
285     }
286 
287     if (record.speedProfile.numSamples() > SAMPLE_THRESHOLD_COMPILER) {
288         printCompilerRecordCSV(appName, "speed-profile", record.speedProfile)
289     }
290 }
291 
printCompilerRecordCSVnull292 fun printCompilerRecordCSV(appName : String, compilerFilter : String, record : CompilerRecord) {
293     if (record.cold.size > SAMPLE_THRESHOLD_TEMPERATURE) {
294         printSampleSetCSV(appName, compilerFilter, "cold", record.cold)
295     }
296 
297     if (record.warm.size > SAMPLE_THRESHOLD_TEMPERATURE) {
298         printSampleSetCSV(appName, compilerFilter, "warm", record.warm)
299     }
300 }
301 
printSampleSetCSVnull302 fun printSampleSetCSV(appName : String, compilerFilter : String, temperature : String, records : List<StartupEvent>) {
303     print("$appName, $compilerFilter, $temperature, ")
304 
305     val (startupTimeAverage, startupTimeStandardDeviation) = averageAndStandardDeviation(records.map {it.endTime - it.startTime})
306     print("%.3f, %.3f, ".format(startupTimeAverage * 1000, startupTimeStandardDeviation * 1000))
307 
308     val (timeToFirstSliceAverage, timeToFirstSliceStandardDeviation) = averageAndStandardDeviation(records.map {it.firstSliceTime - it.startTime})
309     print("%.3f, %.3f,".format(timeToFirstSliceAverage * 1000, timeToFirstSliceStandardDeviation * 1000))
310 
311     if (records.first().reportFullyDrawnTime != null) {
312         val (rfdTimeAverage, rfdTimeStandardDeviation) = averageAndStandardDeviation(records.map { it.reportFullyDrawnTime!! - it.startTime})
313         print(" %.3f, %.3f\n".format(rfdTimeAverage * 1000, rfdTimeStandardDeviation * 1000))
314 
315     } else {
316         print(",\n")
317     }
318 }
319 
320 /*
321  * Main Function
322  */
323 
mainnull324 fun main(args: Array<String>) {
325     if (args.isEmpty()) {
326         println("Usage: StartupSummarizer <trace files>")
327         return
328     }
329 
330     val records : MutableMap<String, ApplicationRecord> = mutableMapOf()
331     val exceptions : MutableList<Pair<String, Exception>> = mutableListOf()
332 
333     var processedFiles = 0
334     var erroredFiles = 0
335 
336     args.forEach { fileName ->
337         val (_, compiler, temperature) = parseFileName(fileName)
338 
339         val trace = parseTrace(File(fileName), false)
340 
341         try {
342             val traceStartupEvents : List<StartupEvent> = trace.getStartupEvents()
343 
344             traceStartupEvents.forEach { startupEvent ->
345                 addStartupRecord(records, startupEvent, startupEvent.name, compiler,
346                                  temperature)
347             }
348 
349         } catch (e: Exception) {
350             exceptions.add(Pair(fileName, e))
351             ++erroredFiles
352         } finally {
353             ++processedFiles
354 
355             print("\rProgress: $processedFiles ($erroredFiles) / ${args.size}")
356         }
357     }
358 
359     println()
360 
361 //    printPlainText(records)
362     printCSV(records)
363 
364     if (exceptions.count() > 0) {
365         println("Exceptions:")
366         exceptions.forEach { (fileName, exception) ->
367             println("\t$fileName: $exception${if (exception.message != null) "(${exception.message})" else ""}")
368         }
369     }
370 }