{"action":"created","issue":{"url":"https://api.github.com/repos/bigdatagenomics/adam/issues/514","labels_url":"https://api.github.com/repos/bigdatagenomics/adam/issues/514/labels{/name}","comments_url":"https://api.github.com/repos/bigdatagenomics/adam/issues/514/comments","events_url":"https://api.github.com/repos/bigdatagenomics/adam/issues/514/events","html_url":"https://github.com/bigdatagenomics/adam/pull/514","id":50460648,"number":514,"title":"Added more granular instrumentation to ADAM","user":{"login":"nfergu","id":1291583,"avatar_url":"https://avatars.githubusercontent.com/u/1291583?v=3","gravatar_id":"","url":"https://api.github.com/users/nfergu","html_url":"https://github.com/nfergu","followers_url":"https://api.github.com/users/nfergu/followers","following_url":"https://api.github.com/users/nfergu/following{/other_user}","gists_url":"https://api.github.com/users/nfergu/gists{/gist_id}","starred_url":"https://api.github.com/users/nfergu/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/nfergu/subscriptions","organizations_url":"https://api.github.com/users/nfergu/orgs","repos_url":"https://api.github.com/users/nfergu/repos","events_url":"https://api.github.com/users/nfergu/events{/privacy}","received_events_url":"https://api.github.com/users/nfergu/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":72,"created_at":"2014-11-30T15:23:57Z","updated_at":"2015-01-25T21:41:41Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/bigdatagenomics/adam/pulls/514","html_url":"https://github.com/bigdatagenomics/adam/pull/514","diff_url":"https://github.com/bigdatagenomics/adam/pull/514.diff","patch_url":"https://github.com/bigdatagenomics/adam/pull/514.patch"},"body":"This includes new instrumentation code to measure timing in Spark operations,\r\nas well as instrumentation of the ADAM Transform operation.\r\n\r\nWhen -print_metrics is specified on the command line this produces output like the following:\r\n\r\n ```\r\nTimings\r\n+----------------------------------------------------------------+-------------+-------------+--------+-----------+-----------+-----------+\r\n|                             Metric                             | Worker Time | Driver Time | Count  |   Mean    |    Min    |    Max    |\r\n+----------------------------------------------------------------+-------------+-------------+--------+-----------+-----------+-----------+\r\n| └─ Load Alignment Records                                      |           - |   534.49 ms |      1 | 534.49 ms | 534.49 ms | 534.49 ms |\r\n|     └─ BAM File Load                                           |           - |   522.82 ms |      1 | 522.82 ms | 522.82 ms | 522.82 ms |\r\n| └─ Trim Reads                                                  |           - |    10.32 ms |      1 |  10.32 ms |         - |         - |\r\n|     ├─ adamFirst at TrimReads.scala:117                        |           - |           - |      1 |         - |         - |         - |\r\n|     └─ adamMap at TrimReads.scala:123                          |           - |           - |      1 |         - |         - |         - |\r\n|         └─ map function                                        |   2.02 secs |           - | 163064 |  12.37 µs |         0 |  11.01 ms |\r\n|             └─ Trim Reads                                      |   1.89 secs |           - | 163064 |  11.58 µs |         0 |   9.08 ms |\r\n|                 └─ Trim Cigar                                  |   122.98 ms |           - | 162311 |    757 ns |         0 |   7.29 ms |\r\n| └─ Mark Duplicates                                             |           - |    13.05 ms |      1 |  13.05 ms |         - |         - |\r\n|     ├─ adamGroupBy at SingleReadBucket.scala:31                |           - |           - |      1 |         - |         - |         - |\r\n|     │   └─ groupBy function                                    |    46.08 ms |           - | 163064 |    282 ns |         0 |     57 µs |\r\n|     ├─ adamMap at SingleReadBucket.scala:32                    |           - |           - |      1 |         - |         - |         - |\r\n|     │   └─ map function                                        |   156.13 ms |           - |  81741 |   1.91 µs |         0 |  28.63 ms |\r\n|     ├─ adamKeyBy at MarkDuplicates.scala:75                    |           - |           - |      1 |         - |         - |         - |\r\n|     │   └─ keyBy function                                      |    525.3 ms |           - |  81741 |   6.43 µs |      1 µs |  34.36 ms |\r\n|     │       └─ Create Reference Position Pair                  |   488.06 ms |           - |  81741 |   5.97 µs |         0 |  34.36 ms |\r\n|     ├─ adamGroupBy at MarkDuplicates.scala:75                  |           - |           - |      1 |         - |         - |         - |\r\n|     │   └─ groupBy function                                    |    48.01 ms |           - |  81741 |    587 ns |         0 |    162 µs |\r\n|     └─ adamFlatMap at MarkDuplicates.scala:76                  |           - |           - |      1 |         - |         - |         - |\r\n|         └─ flatMap function                                    |   874.43 ms |           - |  16999 |  51.44 µs |      2 µs |  42.41 ms |\r\n|             └─ Perform Duplicate Marking                       |   857.33 ms |           - |  16999 |  50.43 µs |      2 µs |  42.41 ms |\r\n|                 └─ Mark Reads                                  |   142.56 ms |           - |  73366 |   1.94 µs |         0 |  38.93 ms |\r\n| └─ Sort Reads                                                  |           - |     8.86 ms |      1 |   8.86 ms |         - |         - |\r\n|     ├─ adamMap at AlignmentRecordRDDFunctions.scala:272        |           - |           - |      1 |         - |         - |         - |\r\n|     │   └─ map function                                        |    42.38 ms |           - | 163064 |    259 ns |         0 |     65 µs |\r\n|     ├─ adamSortByKey at AlignmentRecordRDDFunctions.scala:281  |           - |           - |      1 |         - |         - |         - |\r\n|     └─ adamMap at AlignmentRecordRDDFunctions.scala:281        |           - |           - |      1 |         - |         - |         - |\r\n|         └─ map function                                        |    38.31 ms |           - | 163064 |    234 ns |         0 |     83 µs |\r\n| └─ Save File In ADAM Format                                    |           - |    58.83 ms |      1 |  58.83 ms |         - |         - |\r\n|     ├─ adamMap at ADAMRDDFunctions.scala:80                    |           - |           - |      1 |         - |         - |         - |\r\n|     │   └─ map function                                        |    20.92 ms |           - | 163064 |    128 ns |         0 |     13 µs |\r\n|     └─ adamSaveAsNewAPIHadoopFile at ADAMRDDFunctions.scala:82 |           - |           - |      1 |         - |         - |         - |\r\n|         └─ Write ADAM Record                                   |   5.43 secs |           - | 163064 |  33.29 µs |         0 | 1.13 secs |\r\n+----------------------------------------------------------------+-------------+-------------+--------+-----------+-----------+-----------+\r\n\r\nSpark Operations\r\n+---------------------------------------------------------+--------------+------------+----------+\r\n|                        Operation                        | Is Blocking? |  Duration  | Stage ID |\r\n+---------------------------------------------------------+--------------+------------+----------+\r\n| adamFirst at TrimReads.scala:117                        | true         |     562 ms | 0        |\r\n| adamMap at TrimReads.scala:123                          | false        |          - | -        |\r\n| adamGroupBy at SingleReadBucket.scala:31                | true         | 10.14 secs | 2        |\r\n| adamMap at SingleReadBucket.scala:32                    | false        |          - | -        |\r\n| adamKeyBy at MarkDuplicates.scala:75                    | false        |          - | -        |\r\n| adamGroupBy at MarkDuplicates.scala:75                  | true         |  6.61 secs | 3        |\r\n| adamFlatMap at MarkDuplicates.scala:76                  | false        |          - | -        |\r\n| adamMap at AlignmentRecordRDDFunctions.scala:272        | true         |  9.52 secs | 4        |\r\n| adamSortByKey at AlignmentRecordRDDFunctions.scala:281  | false        |          - | -        |\r\n| adamMap at AlignmentRecordRDDFunctions.scala:281        | false        |          - | -        |\r\n| adamMap at ADAMRDDFunctions.scala:80                    | false        |          - | -        |\r\n| adamSaveAsNewAPIHadoopFile at ADAMRDDFunctions.scala:82 | true         |  9.05 secs | 1        |\r\n+---------------------------------------------------------+--------------+------------+----------+\r\n```\r\n\r\nSome notes:\r\n\r\n* 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.\r\n\r\n* 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.\r\n\r\n* The approach that I've taken is to wrap each Spark RDD operation in an instrumented version. For example, to instrument `map` operations we use the `adamMap` operation instead, which is the instrumented version. \r\n\r\n* 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."},"comment":{"url":"https://api.github.com/repos/bigdatagenomics/adam/issues/comments/71395159","html_url":"https://github.com/bigdatagenomics/adam/pull/514#issuecomment-71395159","issue_url":"https://api.github.com/repos/bigdatagenomics/adam/issues/514","id":71395159,"user":{"login":"massie","id":19554,"avatar_url":"https://avatars.githubusercontent.com/u/19554?v=3","gravatar_id":"","url":"https://api.github.com/users/massie","html_url":"https://github.com/massie","followers_url":"https://api.github.com/users/massie/followers","following_url":"https://api.github.com/users/massie/following{/other_user}","gists_url":"https://api.github.com/users/massie/gists{/gist_id}","starred_url":"https://api.github.com/users/massie/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/massie/subscriptions","organizations_url":"https://api.github.com/users/massie/orgs","repos_url":"https://api.github.com/users/massie/repos","events_url":"https://api.github.com/users/massie/events{/privacy}","received_events_url":"https://api.github.com/users/massie/received_events","type":"User","site_admin":false},"created_at":"2015-01-25T21:41:41Z","updated_at":"2015-01-25T21:41:41Z","body":"Jenkins, test this please."}}