Various perf harness updates. (#152)

- Add a new Instruments template that includes CPU, allocations, virtual memory, and leaks.
- Start outputting the .dylib size as well as the harness binary size.
- Fix brokenness that happened when the code generator's file path handling changed.
- Start measuring JSON encode/decode and equality.
- Add ability to separately print timings for subtasks (the output can be viewed from the Console pane in Instruments).

Performance/Harness.swift

@@ -22,9 +22,14 @@ import Foundation
 /// run() method, which the main.swift file calls.
 class Harness {
 
+  /// The number of times to loop the body of the run() method.
+  var runCount = 100
+
   /// The number of times to call append() for repeated fields.
   let repeatedCount: Int32 = 100
 
+  var subtasks = [String: TimeInterval]()
+
   /// Measures the time it takes to execute the given block. The block is
   /// executed five times and the mean/standard deviation are computed.
   func measure(block: () throws -> Void) {
@@ -33,12 +38,21 @@ class Harness {
     do {
       // Do each measurement 5 times and collect the means and standard
       // deviation to account for noise.
-      for _ in 0..<5 {
+      for attempt in 1...5 {
+        print("Attempt \(attempt), \(runCount) runs:")
+        subtasks.removeAll()
+
         let start = Date()
         try block()
         let end = Date()
         let diff = end.timeIntervalSince(start)
         timings.append(diff)
+
+        for (name, time) in subtasks {
+          print(String(format: "\"%@\" took %.3f sec", name, time))
+        }
+        print(String(format: "Total execution time: %.3f sec\n", diff))
+        print("----")
       }
     } catch let e {
       fatalError("Generated harness threw an error: \(e)")
@@ -46,10 +60,19 @@ class Harness {
 
     let (mean, stddev) = statistics(timings)
 
-    let runtimes = timings.map { String(format: "%.3f", $0) }.joined(separator: ", ")
-    let message = "Runtimes: [\(runtimes)]\n" +
+    let stats =
         String(format: "mean = %.3f sec, stddev = %.3f sec\n", mean, stddev)
-    print(message)
+    print(stats)
+  }
+
+  /// Measure an individual subtask whose timing will be printed separately from the main results.
+  func measureSubtask<Result>(_ name: String, block: () throws -> Result) rethrows -> Result {
+    let start = Date()
+    let result = try block()
+    let end = Date()
+    let diff = end.timeIntervalSince(start)
+    subtasks[name] = (subtasks[name] ?? 0) + diff
+    return result
   }
 
   /// Compute the mean and standard deviation of the given time intervals.

Performance/perf_runner.sh

@@ -92,19 +92,19 @@ function print_swift_set_field() {
   case "$type" in
     repeated\ string)
       echo "        for _ in 0..<repeatedCount {"
-      echo "          msg.field$num.append(\"$((200+num))\")"
+      echo "          message.field$num.append(\"$((200+num))\")"
       echo "        }"
       ;;
     repeated\ *)
       echo "        for _ in 0..<repeatedCount {"
-      echo "          msg.field$num.append($((200+num)))"
+      echo "          message.field$num.append($((200+num)))"
       echo "        }"
       ;;
     string)
-      echo "        msg.field$num = \"$((200+num))\""
+      echo "        message.field$num = \"$((200+num))\""
       ;;
     *)
-      echo "        msg.field$num = $((200+num))"
+      echo "        message.field$num = $((200+num))"
       ;;
   esac
 }
@@ -115,19 +115,46 @@ extension Harness {
   func run() {
     measure {
       // Loop enough times to get meaningfully large measurements.
-      for _ in 0..<200 {
-        var msg = PerfMessage()
+      for _ in 0..<runCount {
+        var message = PerfMessage()
+        measureSubtask("Populate message fields") {
+          populateFields(of: &message)
+        }
+
+        // Exercise binary serialization.
+        let data = try measureSubtask("Encode binary") {
+          return try message.serializeProtobuf()
+        }
+        message = try measureSubtask("Decode binary") {
+          return try PerfMessage(protobuf: data)
+        }
+
+        // Exercise JSON serialization.
+        let json = try measureSubtask("Encode JSON") {
+          return try message.serializeJSON()
+        }
+        let jsonDecodedMessage = try measureSubtask("Decode JSON") {
+          return try PerfMessage(json: json)
+        }
+
+        // Exercise equality.
+        measureSubtask("Test equality") {
+          guard message == jsonDecodedMessage else {
+            fatalError("Binary- and JSON-decoded messages were not equal!")
+          }
+        }
+      }
+    }
+  }
+
+  private func populateFields(of message: inout PerfMessage) {
 EOF
 
   for field_number in $(seq 1 "$field_count"); do
     print_swift_set_field "$field_number" "$field_type" >>"$gen_harness_path"
   done
 
-  cat >>"$gen_harness_path" <<EOF
-        let data = try msg.serializeProtobuf()
-        msg = try PerfMessage(protobuf: data)
-      }
-    }
+  cat >> "$gen_harness_path" <<EOF
   }
 }
 EOF
@@ -163,6 +190,10 @@ readonly field_count=$1
 readonly field_type=$2
 readonly script_dir="$(dirname $0)"
 
+# If the Instruments template has changed since the last run, copy it into the
+# user's template folder. (Would be nice if we could just run the template from
+# the local directory, but Instruments doesn't seem to support that.)
+
 # Make sure the runtime and plug-in are up to date first.
 ( cd "$script_dir/.." >/dev/null; swift build -c release )
 
@@ -186,7 +217,7 @@ echo "Generating test harness..."
 generate_perf_harness "$field_count" "$field_type"
 
 protoc --plugin="$script_dir/../.build/release/protoc-gen-swiftForPerf" \
-    --swiftForPerf_out="$script_dir/_generated" \
+    --swiftForPerf_out=FileNaming=DropPath:"$script_dir/_generated" \
     "$gen_message_path"
 
 echo "Building test harness..."
@@ -203,9 +234,15 @@ time ( swiftc -O -target x86_64-apple-macosx10.10 \
 echo
 
 echo "Running test harness in Instruments..."
-instruments -t "Time Profiler" -D "$results" "$harness"
+instruments -t "$script_dir/Protobuf" -D "$results" "$harness"
 open "$results.trace"
 
+dylib="$script_dir/../.build/release/libSwiftProtobuf.dylib"
+echo "Dylib size before stripping: $(stat -f "%z" "$dylib") bytes"
+strip -u -r "$dylib"
+echo "Dylib size after stripping:  $(stat -f "%z" "$dylib") bytes"
+echo
+
 echo "Harness size before stripping: $(stat -f "%z" "$harness") bytes"
-strip "$harness"
+strip -u -r "$harness"
 echo "Harness size after stripping:  $(stat -f "%z" "$harness") bytes"