bigdatagenomics/adam — pull request #514 by nfergu (2014-11-30 15:23:57+00:00)
Title: Added more granular instrumentation to ADAM

This includes new instrumentation code to measure timing in Spark operations,
as well as instrumentation of the ADAM Transform operation.

When -print_metrics is specified on the command line this produces output like the following:

```
Timings
+----------------------------------------------------------------+-------------+-------------+--------+-----------+-----------+-----------+
| Metric | Worker Time | Driver Time | Count | Mean | Min | Max |
+----------------------------------------------------------------+-------------+-------------+--------+-----------+-----------+-----------+
| └─ Load Alignment Records | - | 534.49 ms | 1 | 534.49 ms | 534.49 ms | 534.49 ms |
| └─ BAM File Load | - | 522.82 ms | 1 | 522.82 ms | 522.82 ms | 522.82 ms |
| └─ Trim Reads | - | 10.32 ms | 1 | 10.32 ms | - | - |
| ├─ adamFirst at TrimReads.scala:117 | - | - | 1 | - | - | - |
| └─ adamMap at TrimReads.scala:123 | - | - | 1 | - | - | - |
| └─ map function | 2.02 secs | - | 163064 | 12.37 µs | 0 | 11.01 ms |
| └─ Trim Reads | 1.89 secs | - | 163064 | 11.58 µs | 0 | 9.08 ms |
| └─ Trim Cigar | 122.98 ms | - | 162311 | 757 ns | 0 | 7.29 ms |
| └─ Mark Duplicates | - | 13.05 ms | 1 | 13.05 ms | - | - |
| ├─ adamGroupBy at SingleReadBucket.scala:31 | - | - | 1 | - | - | - |
| │ └─ groupBy function | 46.08 ms | - | 163064 | 282 ns | 0 | 57 µs |
| ├─ adamMap at SingleReadBucket.scala:32 | - | - | 1 | - | - | - |
| │ └─ map function | 156.13 ms | - | 81741 | 1.91 µs | 0 | 28.63 ms |
| ├─ adamKeyBy at MarkDuplicates.scala:75 | - | - | 1 | - | - | - |
| │ └─ keyBy function | 525.3 ms | - | 81741 | 6.43 µs | 1 µs | 34.36 ms |
| │ └─ Create Reference Position Pair | 488.06 ms | - | 81741 | 5.97 µs | 0 | 34.36 ms |
| ├─ adamGroupBy at MarkDuplicates.scala:75 | - | - | 1 | - | - | - |
| │ └─ groupBy function | 48.01 ms | - | 81741 | 587 ns | 0 | 162 µs |
| └─ adamFlatMap at MarkDuplicates.scala:76 | - | - | 1 | - | - | - |
| └─ flatMap function | 874.43 ms | - | 16999 | 51.44 µs | 2 µs | 42.41 ms |
| └─ Perform Duplicate Marking | 857.33 ms | - | 16999 | 50.43 µs | 2 µs | 42.41 ms |
| └─ Mark Reads | 142.56 ms | - | 73366 | 1.94 µs | 0 | 38.93 ms |
| └─ Sort Reads | - | 8.86 ms | 1 | 8.86 ms | - | - |
| ├─ adamMap at AlignmentRecordRDDFunctions.scala:272 | - | - | 1 | - | - | - |
| │ └─ map function | 42.38 ms | - | 163064 | 259 ns | 0 | 65 µs |
| ├─ adamSortByKey at AlignmentRecordRDDFunctions.scala:281 | - | - | 1 | - | - | - |
| └─ adamMap at AlignmentRecordRDDFunctions.scala:281 | - | - | 1 | - | - | - |
| └─ map function | 38.31 ms | - | 163064 | 234 ns | 0 | 83 µs |
| └─ Save File In ADAM Format | - | 58.83 ms | 1 | 58.83 ms | - | - |
| ├─ adamMap at ADAMRDDFunctions.scala:80 | - | - | 1 | - | - | - |
| │ └─ map function | 20.92 ms | - | 163064 | 128 ns | 0 | 13 µs |
| └─ adamSaveAsNewAPIHadoopFile at ADAMRDDFunctions.scala:82 | - | - | 1 | - | - | - |
| └─ Write ADAM Record | 5.43 secs | - | 163064 | 33.29 µs | 0 | 1.13 secs |
+----------------------------------------------------------------+-------------+-------------+--------+-----------+-----------+-----------+

Spark Operations
+---------------------------------------------------------+--------------+------------+----------+
| Operation | Is Blocking? | Duration | Stage ID |
+---------------------------------------------------------+--------------+------------+----------+
| adamFirst at TrimReads.scala:117 | true | 562 ms | 0 |
| adamMap at TrimReads.scala:123 | false | - | - |
| adamGroupBy at SingleReadBucket.scala:31 | true | 10.14 secs | 2 |
| adamMap at SingleReadBucket.scala:32 | false | - | - |
| adamKeyBy at MarkDuplicates.scala:75 | false | - | - |
| adamGroupBy at MarkDuplicates.scala:75 | true | 6.61 secs | 3 |
| adamFlatMap at MarkDuplicates.scala:76 | false | - | - |
| adamMap at AlignmentRecordRDDFunctions.scala:272 | true | 9.52 secs | 4 |
| adamSortByKey at AlignmentRecordRDDFunctions.scala:281 | false | - | - |
| adamMap at AlignmentRecordRDDFunctions.scala:281 | false | - | - |
| adamMap at ADAMRDDFunctions.scala:80 | false | - | - |
| adamSaveAsNewAPIHadoopFile at ADAMRDDFunctions.scala:82 | true | 9.05 secs | 1 |
+---------------------------------------------------------+--------------+------------+----------+
```

Some notes:

* Sorry for the gigantic PR! I got a bit carried away. However, most of the changes should be isolated to the instrumentation package, so hopefully it's not too much of a pain to review.

* I have instrumented the ADAM Transform command. Therefore there are quite a few files changed in the core ADAM code, but these changes should be isolated to changing RDD operations to use the instrumented version, and addition of timers.

* Some of the code for instrumenting Spark RDD operations needs to go in the org.spark.rdd package for now, which is clearly a bit weird. This is so that Spark uses the correct call-site (and therefore stage name). I believe that this can be changed when we upgrade to Spark 1.1.1, which includes SPARK-1853 -- this fixes an issue with overriding call-sites. Instead of using the org.spark.rdd package we can just override the call-site instead.