Class org.broadinstitute.hellbender.tools.spark.pipelines.MarkDuplicatesSparkIntegrationTest

all > org.broadinstitute.hellbender.tools.spark.pipelines > MarkDuplicatesSparkIntegrationTest
152

tests
0

failures
0

ignored
1m11.47s

duration
100%

successful

Tests

Test Duration Result
assertThatExpectedOutputUpdateToggleIsDisabled 0s passed
testAssertAssumeUnsortedFilesAreQueryGroupedFiles 0.661s passed
testAssertCorrectSortOrderMultipleBams 0.186s passed
testAssertCorrectSortOrderMultipleBamsOverriding 0.596s passed
testBulkFragmentsNoDuplicates 1.290s passed
testBulkFragmentsWithDuplicates 2.293s passed
testDifferentChromosomesInOppositeOrder 0.383s passed
testDuplicateDetectionDataProviderWithMetrics[0](src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/example.chr1.1-1K.unmarkedDups.bam, src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/expected.picard-2.15.0.sorted.chr1.1-1K.unmarkedDups.markDuplicate.metrics) 0.363s passed
testDuplicateDetectionDataProviderWithMetrics[1](src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/optical_dupes.bam, src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/expected.picard-2.15.0.sorted.optical_dupes.markDuplicate.metrics) 0.269s passed
testDuplicateDetectionDataProviderWithMetrics[2](src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/inputSingleLibrarySolexa16404.bam, src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/expected.picard-2.15.0.sorted.inputSingleLibrarySolexa16404.metrics) 0.319s passed
testFlowModeFlag 2.135s passed
testHashCollisionHandling 1.235s passed
testMDOrder[0](src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug.bam, src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/expected.mdOrderBug.bam) 0.362s passed
testMDOrder[1](src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug2.bam, src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/expected.mdOrderBug2.bam) 0.340s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[0](true, true, true) 0.373s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[1](true, false, true) 0.376s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[2](false, true, true) 0.388s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[3](true, true, false) 0.373s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[4](true, false, false) 0.391s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[5](false, true, false) 0.401s passed
testMappedFragmentAndMappedPairFirstOfPairNonPrimary 0.373s passed
testMappedFragmentAndMatePairFirstUnmapped 0.339s passed
testMappedFragmentAndMatePairSecondUnmapped 0.370s passed
testMappedPairAndMappedFragmentAndMatePairFirstUnmapped 0.387s passed
testMappedPairAndMappedFragmentAndMatePairSecondUnmapped 0.413s passed
testMappedPairAndMatePairFirstOppositeStrandSecondUnmapped 0.401s passed
testMappedPairAndMatePairFirstUnmapped 0.381s passed
testMappedPairAndMatePairSecondUnmapped 0.378s passed
testMappedPairWithFirstEndSamePositionAndOther 0.333s passed
testMappedPairWithSamePosition 0.336s passed
testMappedPairWithSamePositionSameCigar 0.339s passed
testMarkDuplicatesSparkDeletingDuplicateReads[0]([Ljava.io.File;@72cb11a6, 20, 0, {Solexa-16419=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16416=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16404=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16406=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16412=[0, 1, 0, 0, 0, 0, 0.0, 0]}) 0.434s passed
testMarkDuplicatesSparkDeletingDuplicateReads[1]([Ljava.io.File;@22d67a67, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.467s passed
testMarkDuplicatesSparkDeletingDuplicateReads[2]([Ljava.io.File;@60a22df6, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.447s passed
testMarkDuplicatesSparkDeletingDuplicateReads[3]([Ljava.io.File;@1e0f55be, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.411s passed
testMarkDuplicatesSparkDeletingDuplicateReads[4]([Ljava.io.File;@67f51ef, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.404s passed
testMarkDuplicatesSparkDeletingDuplicateReads[5]([Ljava.io.File;@43e66b03, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.320s passed
testMarkDuplicatesSparkDeletingDuplicateReads[6]([Ljava.io.File;@174211b6, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.389s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[0]([Ljava.io.File;@430c267a, 20, 0, {Solexa-16419=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16416=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16404=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16406=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16412=[0, 1, 0, 0, 0, 0, 0.0, 0]}) 0.414s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[1]([Ljava.io.File;@6fa2793c, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.451s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[2]([Ljava.io.File;@37828bd1, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.465s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[3]([Ljava.io.File;@6806daca, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.428s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[4]([Ljava.io.File;@6521e339, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.416s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[5]([Ljava.io.File;@40a70266, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.320s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[6]([Ljava.io.File;@40b5563, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.314s passed
testMarkDuplicatesSparkIntegrationTestLocal[0]([Ljava.io.File;@642219d2, 20, 0, {Solexa-16419=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16416=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16404=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16406=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16412=[0, 1, 0, 0, 0, 0, 0.0, 0]}) 0.439s passed
testMarkDuplicatesSparkIntegrationTestLocal[1]([Ljava.io.File;@1c8bdc6a, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.393s passed
testMarkDuplicatesSparkIntegrationTestLocal[2]([Ljava.io.File;@7ad017c7, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.434s passed
testMarkDuplicatesSparkIntegrationTestLocal[3]([Ljava.io.File;@20f69eea, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.403s passed
testMarkDuplicatesSparkIntegrationTestLocal[4]([Ljava.io.File;@120ade3a, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.401s passed
testMarkDuplicatesSparkIntegrationTestLocal[5]([Ljava.io.File;@1216096b, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.242s passed
testMarkDuplicatesSparkIntegrationTestLocal[6]([Ljava.io.File;@57bb18a, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.353s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[0]([Ljava.io.File;@40950cc6, 20, 0, {Solexa-16419=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16416=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16404=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16406=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16412=[0, 1, 0, 0, 0, 0, 0.0, 0]}) 0.417s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[1]([Ljava.io.File;@2803e0e0, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.437s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[2]([Ljava.io.File;@70d75862, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.411s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[3]([Ljava.io.File;@4e703d4a, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.403s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[4]([Ljava.io.File;@1be1dc6e, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.377s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[5]([Ljava.io.File;@77f4f6a2, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.209s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[6]([Ljava.io.File;@2736454d, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.204s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[0]([Ljava.io.File;@d8ab6b8, 20, 0, {Solexa-16419=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16416=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16404=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16406=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16412=[0, 1, 0, 0, 0, 0, 0.0, 0]}) 0.376s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[1]([Ljava.io.File;@2a387f4c, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.388s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[2]([Ljava.io.File;@1abe93c3, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.380s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[3]([Ljava.io.File;@6e766094, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.360s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[4]([Ljava.io.File;@74cc7281, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.336s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[5]([Ljava.io.File;@1f15f35d, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.207s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[6]([Ljava.io.File;@b8d2f17, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.206s passed
testMatePairFirstUnmapped 0.346s passed
testMatePairSecondUnmapped 0.386s passed
testNoReadGroupInRead 0.322s passed
testNonExistantReadGroupInRead 0.289s passed
testNullOpticalDuplicates 0.390s passed
testOpticalDuplicateClusterOneEndSamePositionOneCluster 0.395s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicatesWithinPixelDistance 0.360s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[0](RUNID:7:1203:2886:82292, RUNID:7:1205:3886:16834) 0.379s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[10](RUNID:7:1203:6886:16756, RUNID:7:1203:4886:26756) 0.360s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[11](RUNID:7:1203:2886:34756, RUNID:7:1203:2886:36756) 0.329s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[12](RUNID:7:1203:2886:35756, RUNID:7:1203:2886:36756) 0.355s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[13](RUNID:7:1203:2886:37756, RUNID:7:1203:2886:36756) 0.380s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[14](RUNID:7:1203:2886:38756, RUNID:7:1203:2886:36756) 0.395s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[15](HK3T5CCXX160204:3:1112:11586:37067, HK3T5CCXX160204:3:1112:11586:32144) 0.335s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[1](RUNID:7:1203:2886:16756, RUNID:7:1205:3886:16756) 0.377s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[2](RUNID:7:1204:2886:16756, RUNID:7:1205:3886:16756) 0.381s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[3](RUNID:7:1205:2886:16756, RUNID:7:1205:3886:16756) 0.364s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[4](RUNID:7:1206:2886:16756, RUNID:7:1205:3886:16756) 0.335s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[5](RUNID:7:1207:2886:16756, RUNID:7:1205:3886:16756) 0.388s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[6](RUNID:7:1203:2886:16756, RUNID:7:1203:4886:26756) 0.370s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[7](RUNID:7:1203:3886:16756, RUNID:7:1203:4886:26756) 0.390s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[8](RUNID:7:1203:4886:16756, RUNID:7:1203:4886:26756) 0.367s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[9](RUNID:7:1203:5886:16756, RUNID:7:1203:4886:26756) 0.383s passed
testOpticalDuplicateClusterSamePositionOneOpticalDuplicatesWithinPixelDistance 0.361s passed
testOpticalDuplicateClustersAddingSecondEndFirstSameCoordinate 0.338s passed
testOpticalDuplicateFinding 0.345s passed
testOpticalDuplicateFindingPxelDistance 0.332s passed
testOpticalDuplicatesAndPCRDuplicatesOrientationDifference 0.333s passed
testOpticalDuplicatesDifferentReadGroups 0.331s passed
testOpticalDuplicatesTheSameReadGroup 0.334s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[0](RUNID:7:1203:2886:82292, RUNID:7:1205:3886:16834) 0.347s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[10](RUNID:7:1203:6886:16756, RUNID:7:1203:4886:26756) 0.344s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[11](RUNID:7:1203:2886:34756, RUNID:7:1203:2886:36756) 0.333s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[12](RUNID:7:1203:2886:35756, RUNID:7:1203:2886:36756) 0.367s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[13](RUNID:7:1203:2886:37756, RUNID:7:1203:2886:36756) 0.396s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[14](RUNID:7:1203:2886:38756, RUNID:7:1203:2886:36756) 0.377s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[15](HK3T5CCXX160204:3:1112:11586:37067, HK3T5CCXX160204:3:1112:11586:32144) 0.384s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[1](RUNID:7:1203:2886:16756, RUNID:7:1205:3886:16756) 0.395s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[2](RUNID:7:1204:2886:16756, RUNID:7:1205:3886:16756) 0.379s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[3](RUNID:7:1205:2886:16756, RUNID:7:1205:3886:16756) 0.371s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[4](RUNID:7:1206:2886:16756, RUNID:7:1205:3886:16756) 0.376s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[5](RUNID:7:1207:2886:16756, RUNID:7:1205:3886:16756) 0.375s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[6](RUNID:7:1203:2886:16756, RUNID:7:1203:4886:26756) 0.368s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[7](RUNID:7:1203:3886:16756, RUNID:7:1203:4886:26756) 0.399s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[8](RUNID:7:1203:4886:16756, RUNID:7:1203:4886:26756) 0.358s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[9](RUNID:7:1203:5886:16756, RUNID:7:1203:4886:26756) 0.349s passed
testPathologicalOrderingAtTheSamePosition 0.380s passed
testReadSameStartPositionOrientationOverride 0.378s passed
testReadsHaveSameStartPositionButDifferentChromosomeNonEquivalence 0.380s passed
testSecondEndIsBeforeFirstInCoordinate 0.382s passed
testSingleMappedFragment 0.385s passed
testSingleMappedFragmentAndSingleMappedPair 0.377s passed
testSingleMappedFragmentAndTwoMappedPairs 0.355s passed
testSingleMappedPair 0.375s passed
testSingleUnmappedFragment 0.347s passed
testSingleUnmappedPair 0.391s passed
testStackOverFlowPairSetSwap 0.378s passed
testSupplementaryReadUnmappedMate 0.371s passed
testThreeGroupsOnDifferentChromosomesOfThreeMappedPairs 0.371s passed
testThreeMappedPairs 0.364s passed
testThreeMappedPairsWithMatchingSecondMate 0.393s passed
testTwoGroupsOnDifferentChromosomesOfThreeMappedPairs 0.351s passed
testTwoGroupsOnDifferentChromosomesOfTwoFragments 0.356s passed
testTwoGroupsOnDifferentChromosomesOfTwoMappedPairs 0.386s passed
testTwoMappedFragments 0.368s passed
testTwoMappedPairWithSamePosition 0.386s passed
testTwoMappedPairWithSamePositionDifferentStrands 0.391s passed
testTwoMappedPairWithSamePositionDifferentStrands2 0.361s passed
testTwoMappedPairs 0.371s passed
testTwoMappedPairsAndMappedSecondaryFragment 0.372s passed
testTwoMappedPairsAndTerminalUnmappedFragment 0.371s passed
testTwoMappedPairsAndTerminalUnmappedPair 0.382s passed
testTwoMappedPairsMatesSoftClipped 0.377s passed
testTwoMappedPairsWithOppositeOrientations 0.377s passed
testTwoMappedPairsWithOppositeOrientationsNumberTwo 0.366s passed
testTwoMappedPairsWithSoftClipping 0.394s passed
testTwoMappedPairsWithSoftClippingBoth 0.399s passed
testTwoMappedPairsWithSoftClippingFirstOfPairOnly 0.374s passed
testTwoMappedPairsWithSoftClippingFirstOfPairOnlyNoMateCigar 0.360s passed
testTwoMappedPairsWithSupplementaryReads[0](true, true, true) 0.375s passed
testTwoMappedPairsWithSupplementaryReads[1](true, false, true) 0.378s passed
testTwoMappedPairsWithSupplementaryReads[2](false, true, true) 0.374s passed
testTwoMappedPairsWithSupplementaryReads[3](true, true, false) 0.370s passed
testTwoMappedPairsWithSupplementaryReads[4](true, false, false) 0.381s passed
testTwoMappedPairsWithSupplementaryReads[5](false, true, false) 0.374s passed
testTwoUnmappedFragments 0.342s passed

Standard error

[May 27, 2025 at 6:31:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:39 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:41 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
18:31:41.383 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:31:41.383 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) v06789f4-SNAPSHOT
18:31:41.383 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:31:41.383 INFO  MarkDuplicatesSpark - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:31:41.383 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:31:41.383 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:31:41 PM GMT
18:31:41.383 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:31:41.383 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:31:41.384 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:31:41.384 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
18:31:41.384 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
18:31:41.384 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:31:41.384 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:31:41.384 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:31:41.384 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:31:41.384 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:31:41.384 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:31:41.384 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:31:41.384 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:31:41.384 INFO  MarkDuplicatesSpark - Initializing engine
18:31:41.384 INFO  MarkDuplicatesSpark - Done initializing engine
18:31:41.384 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:31:41.387 INFO  MemoryStore - Block broadcast_1337 stored as values in memory (estimated size 305.5 KiB, free 1898.9 MiB)
18:31:41.395 INFO  MemoryStore - Block broadcast_1337_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1898.8 MiB)
18:31:41.395 INFO  BlockManagerInfo - Added broadcast_1337_piece0 in memory on localhost:38805 (size: 64.0 KiB, free: 1918.8 MiB)
18:31:41.396 INFO  SparkContext - Created broadcast 1337 from newAPIHadoopFile at PathSplitSource.java:96
18:31:41.419 INFO  MemoryStore - Block broadcast_1338 stored as values in memory (estimated size 305.5 KiB, free 1898.5 MiB)
18:31:41.426 INFO  MemoryStore - Block broadcast_1338_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1898.5 MiB)
18:31:41.426 INFO  BlockManagerInfo - Added broadcast_1338_piece0 in memory on localhost:38805 (size: 64.0 KiB, free: 1918.7 MiB)
18:31:41.427 INFO  SparkContext - Created broadcast 1338 from newAPIHadoopFile at PathSplitSource.java:96
18:31:41.462 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:31:41.462 INFO  FileInputFormat - Total input files to process : 1
18:31:41.464 INFO  DAGScheduler - Registering RDD 3396 (mapToPair at SparkUtils.java:161) as input to shuffle 97
18:31:41.464 INFO  DAGScheduler - Got job 413 (collect at SparkUtils.java:205) with 1 output partitions
18:31:41.465 INFO  DAGScheduler - Final stage: ResultStage 721 (collect at SparkUtils.java:205)
18:31:41.465 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 720)
18:31:41.465 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 720)
18:31:41.466 INFO  DAGScheduler - Submitting ShuffleMapStage 720 (MapPartitionsRDD[3396] at mapToPair at SparkUtils.java:161), which has no missing parents
18:31:41.484 INFO  MemoryStore - Block broadcast_1339 stored as values in memory (estimated size 459.2 KiB, free 1898.0 MiB)
18:31:41.487 INFO  MemoryStore - Block broadcast_1339_piece0 stored as bytes in memory (estimated size 201.4 KiB, free 1897.8 MiB)
18:31:41.487 INFO  BlockManagerInfo - Added broadcast_1339_piece0 in memory on localhost:38805 (size: 201.4 KiB, free: 1918.5 MiB)
18:31:41.488 INFO  SparkContext - Created broadcast 1339 from broadcast at DAGScheduler.scala:1580
18:31:41.488 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 720 (MapPartitionsRDD[3396] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:31:41.489 INFO  TaskSchedulerImpl - Adding task set 720.0 with 1 tasks resource profile 0
18:31:41.489 INFO  TaskSetManager - Starting task 0.0 in stage 720.0 (TID 650) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9650 bytes) 
18:31:41.491 INFO  Executor - Running task 0.0 in stage 720.0 (TID 650)
18:31:41.524 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug.bam:0+1507
18:31:41.529 INFO  Executor - Finished task 0.0 in stage 720.0 (TID 650). 1148 bytes result sent to driver
18:31:41.529 INFO  TaskSetManager - Finished task 0.0 in stage 720.0 (TID 650) in 40 ms on localhost (executor driver) (1/1)
18:31:41.530 INFO  TaskSchedulerImpl - Removed TaskSet 720.0, whose tasks have all completed, from pool 
18:31:41.530 INFO  DAGScheduler - ShuffleMapStage 720 (mapToPair at SparkUtils.java:161) finished in 0.064 s
18:31:41.530 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.530 INFO  DAGScheduler - running: HashSet()
18:31:41.530 INFO  DAGScheduler - waiting: HashSet(ResultStage 721)
18:31:41.531 INFO  DAGScheduler - failed: HashSet()
18:31:41.531 INFO  DAGScheduler - Submitting ResultStage 721 (MapPartitionsRDD[3399] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:31:41.532 INFO  MemoryStore - Block broadcast_1340 stored as values in memory (estimated size 7.4 KiB, free 1897.8 MiB)
18:31:41.533 INFO  MemoryStore - Block broadcast_1340_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1897.8 MiB)
18:31:41.533 INFO  BlockManagerInfo - Added broadcast_1340_piece0 in memory on localhost:38805 (size: 4.1 KiB, free: 1918.5 MiB)
18:31:41.533 INFO  SparkContext - Created broadcast 1340 from broadcast at DAGScheduler.scala:1580
18:31:41.533 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 721 (MapPartitionsRDD[3399] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:31:41.534 INFO  TaskSchedulerImpl - Adding task set 721.0 with 1 tasks resource profile 0
18:31:41.535 INFO  TaskSetManager - Starting task 0.0 in stage 721.0 (TID 651) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:31:41.535 INFO  Executor - Running task 0.0 in stage 721.0 (TID 651)
18:31:41.537 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.537 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.540 INFO  Executor - Finished task 0.0 in stage 721.0 (TID 651). 2281 bytes result sent to driver
18:31:41.541 INFO  TaskSetManager - Finished task 0.0 in stage 721.0 (TID 651) in 6 ms on localhost (executor driver) (1/1)
18:31:41.541 INFO  TaskSchedulerImpl - Removed TaskSet 721.0, whose tasks have all completed, from pool 
18:31:41.541 INFO  DAGScheduler - ResultStage 721 (collect at SparkUtils.java:205) finished in 0.010 s
18:31:41.541 INFO  DAGScheduler - Job 413 is finished. Cancelling potential speculative or zombie tasks for this job
18:31:41.541 INFO  TaskSchedulerImpl - Killing all running tasks in stage 721: Stage finished
18:31:41.541 INFO  DAGScheduler - Job 413 finished: collect at SparkUtils.java:205, took 0.079441 s
18:31:41.548 INFO  MemoryStore - Block broadcast_1341 stored as values in memory (estimated size 1632.0 B, free 1897.8 MiB)
18:31:41.548 INFO  MemoryStore - Block broadcast_1341_piece0 stored as bytes in memory (estimated size 145.0 B, free 1897.8 MiB)
18:31:41.549 INFO  BlockManagerInfo - Added broadcast_1341_piece0 in memory on localhost:38805 (size: 145.0 B, free: 1918.5 MiB)
18:31:41.549 INFO  SparkContext - Created broadcast 1341 from broadcast at MarkDuplicatesSparkUtils.java:126
18:31:41.550 INFO  MemoryStore - Block broadcast_1342 stored as values in memory (estimated size 304.0 B, free 1897.8 MiB)
18:31:41.550 INFO  MemoryStore - Block broadcast_1342_piece0 stored as bytes in memory (estimated size 37.0 B, free 1897.8 MiB)
18:31:41.551 INFO  BlockManagerInfo - Added broadcast_1342_piece0 in memory on localhost:38805 (size: 37.0 B, free: 1918.5 MiB)
18:31:41.551 INFO  SparkContext - Created broadcast 1342 from broadcast at MarkDuplicatesSparkUtils.java:127
18:31:41.566 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:31:41.567 INFO  DAGScheduler - Registering RDD 3408 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 100
18:31:41.567 INFO  DAGScheduler - Registering RDD 3412 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 99
18:31:41.567 INFO  DAGScheduler - Registering RDD 3416 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 98
18:31:41.568 INFO  DAGScheduler - Got job 414 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:31:41.568 INFO  DAGScheduler - Final stage: ResultStage 726 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:31:41.568 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 725)
18:31:41.568 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 725)
18:31:41.568 INFO  DAGScheduler - Submitting ShuffleMapStage 723 (MapPartitionsRDD[3408] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:31:41.569 INFO  MemoryStore - Block broadcast_1343 stored as values in memory (estimated size 24.2 KiB, free 1897.8 MiB)
18:31:41.570 INFO  MemoryStore - Block broadcast_1343_piece0 stored as bytes in memory (estimated size 12.6 KiB, free 1897.8 MiB)
18:31:41.570 INFO  BlockManagerInfo - Added broadcast_1343_piece0 in memory on localhost:38805 (size: 12.6 KiB, free: 1918.5 MiB)
18:31:41.571 INFO  SparkContext - Created broadcast 1343 from broadcast at DAGScheduler.scala:1580
18:31:41.571 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 723 (MapPartitionsRDD[3408] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:31:41.571 INFO  TaskSchedulerImpl - Adding task set 723.0 with 1 tasks resource profile 0
18:31:41.573 INFO  TaskSetManager - Starting task 0.0 in stage 723.0 (TID 652) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
18:31:41.573 INFO  Executor - Running task 0.0 in stage 723.0 (TID 652)
18:31:41.576 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.576 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.581 INFO  Executor - Finished task 0.0 in stage 723.0 (TID 652). 1922 bytes result sent to driver
18:31:41.582 INFO  TaskSetManager - Finished task 0.0 in stage 723.0 (TID 652) in 9 ms on localhost (executor driver) (1/1)
18:31:41.582 INFO  TaskSchedulerImpl - Removed TaskSet 723.0, whose tasks have all completed, from pool 
18:31:41.582 INFO  DAGScheduler - ShuffleMapStage 723 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.014 s
18:31:41.582 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.582 INFO  DAGScheduler - running: HashSet()
18:31:41.582 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 724, ShuffleMapStage 725, ResultStage 726)
18:31:41.582 INFO  DAGScheduler - failed: HashSet()
18:31:41.583 INFO  DAGScheduler - Submitting ShuffleMapStage 724 (MapPartitionsRDD[3412] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:31:41.584 INFO  MemoryStore - Block broadcast_1344 stored as values in memory (estimated size 28.3 KiB, free 1897.7 MiB)
18:31:41.585 INFO  MemoryStore - Block broadcast_1344_piece0 stored as bytes in memory (estimated size 14.8 KiB, free 1897.7 MiB)
18:31:41.585 INFO  BlockManagerInfo - Added broadcast_1344_piece0 in memory on localhost:38805 (size: 14.8 KiB, free: 1918.5 MiB)
18:31:41.586 INFO  SparkContext - Created broadcast 1344 from broadcast at DAGScheduler.scala:1580
18:31:41.586 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 724 (MapPartitionsRDD[3412] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:31:41.586 INFO  TaskSchedulerImpl - Adding task set 724.0 with 1 tasks resource profile 0
18:31:41.587 INFO  TaskSetManager - Starting task 0.0 in stage 724.0 (TID 653) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
18:31:41.587 INFO  Executor - Running task 0.0 in stage 724.0 (TID 653)
18:31:41.590 INFO  ShuffleBlockFetcherIterator - Getting 1 (129.0 B) non-empty blocks including 1 (129.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.590 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.595 INFO  Executor - Finished task 0.0 in stage 724.0 (TID 653). 1922 bytes result sent to driver
18:31:41.596 INFO  TaskSetManager - Finished task 0.0 in stage 724.0 (TID 653) in 10 ms on localhost (executor driver) (1/1)
18:31:41.596 INFO  TaskSchedulerImpl - Removed TaskSet 724.0, whose tasks have all completed, from pool 
18:31:41.596 INFO  DAGScheduler - ShuffleMapStage 724 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.013 s
18:31:41.596 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.596 INFO  DAGScheduler - running: HashSet()
18:31:41.597 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 725, ResultStage 726)
18:31:41.597 INFO  DAGScheduler - failed: HashSet()
18:31:41.597 INFO  DAGScheduler - Submitting ShuffleMapStage 725 (MapPartitionsRDD[3416] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:31:41.598 INFO  MemoryStore - Block broadcast_1345 stored as values in memory (estimated size 19.0 KiB, free 1897.7 MiB)
18:31:41.598 INFO  MemoryStore - Block broadcast_1345_piece0 stored as bytes in memory (estimated size 9.7 KiB, free 1897.7 MiB)
18:31:41.599 INFO  BlockManagerInfo - Added broadcast_1345_piece0 in memory on localhost:38805 (size: 9.7 KiB, free: 1918.5 MiB)
18:31:41.599 INFO  SparkContext - Created broadcast 1345 from broadcast at DAGScheduler.scala:1580
18:31:41.599 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 725 (MapPartitionsRDD[3416] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:31:41.599 INFO  TaskSchedulerImpl - Adding task set 725.0 with 1 tasks resource profile 0
18:31:41.600 INFO  TaskSetManager - Starting task 0.0 in stage 725.0 (TID 654) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:31:41.600 INFO  Executor - Running task 0.0 in stage 725.0 (TID 654)
18:31:41.603 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.603 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.605 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.606 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.608 INFO  Executor - Finished task 0.0 in stage 725.0 (TID 654). 1922 bytes result sent to driver
18:31:41.608 INFO  TaskSetManager - Finished task 0.0 in stage 725.0 (TID 654) in 8 ms on localhost (executor driver) (1/1)
18:31:41.608 INFO  TaskSchedulerImpl - Removed TaskSet 725.0, whose tasks have all completed, from pool 
18:31:41.608 INFO  DAGScheduler - ShuffleMapStage 725 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.011 s
18:31:41.609 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.609 INFO  DAGScheduler - running: HashSet()
18:31:41.609 INFO  DAGScheduler - waiting: HashSet(ResultStage 726)
18:31:41.609 INFO  DAGScheduler - failed: HashSet()
18:31:41.609 INFO  DAGScheduler - Submitting ResultStage 726 (MapPartitionsRDD[3418] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:31:41.610 INFO  MemoryStore - Block broadcast_1346 stored as values in memory (estimated size 20.2 KiB, free 1897.7 MiB)
18:31:41.611 INFO  MemoryStore - Block broadcast_1346_piece0 stored as bytes in memory (estimated size 10.6 KiB, free 1897.7 MiB)
18:31:41.611 INFO  BlockManagerInfo - Added broadcast_1346_piece0 in memory on localhost:38805 (size: 10.6 KiB, free: 1918.5 MiB)
18:31:41.611 INFO  SparkContext - Created broadcast 1346 from broadcast at DAGScheduler.scala:1580
18:31:41.612 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 726 (MapPartitionsRDD[3418] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:31:41.612 INFO  TaskSchedulerImpl - Adding task set 726.0 with 1 tasks resource profile 0
18:31:41.612 INFO  TaskSetManager - Starting task 0.0 in stage 726.0 (TID 655) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:31:41.613 INFO  Executor - Running task 0.0 in stage 726.0 (TID 655)
18:31:41.615 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.615 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.618 INFO  Executor - Finished task 0.0 in stage 726.0 (TID 655). 1944 bytes result sent to driver
18:31:41.618 INFO  TaskSetManager - Finished task 0.0 in stage 726.0 (TID 655) in 6 ms on localhost (executor driver) (1/1)
18:31:41.618 INFO  TaskSchedulerImpl - Removed TaskSet 726.0, whose tasks have all completed, from pool 
18:31:41.619 INFO  DAGScheduler - ResultStage 726 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.009 s
18:31:41.619 INFO  DAGScheduler - Job 414 is finished. Cancelling potential speculative or zombie tasks for this job
18:31:41.619 INFO  TaskSchedulerImpl - Killing all running tasks in stage 726: Stage finished
18:31:41.619 INFO  DAGScheduler - Job 414 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.052680 s
18:31:41.630 INFO  MemoryStore - Block broadcast_1347 stored as values in memory (estimated size 20.3 KiB, free 1897.6 MiB)
18:31:41.631 INFO  MemoryStore - Block broadcast_1347_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1897.6 MiB)
18:31:41.631 INFO  BlockManagerInfo - Added broadcast_1347_piece0 in memory on localhost:38805 (size: 1850.0 B, free: 1918.5 MiB)
18:31:41.632 INFO  SparkContext - Created broadcast 1347 from broadcast at ReadsSparkSink.java:133
18:31:41.632 INFO  MemoryStore - Block broadcast_1348 stored as values in memory (estimated size 20.4 KiB, free 1897.6 MiB)
18:31:41.633 INFO  MemoryStore - Block broadcast_1348_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1897.6 MiB)
18:31:41.633 INFO  BlockManagerInfo - Added broadcast_1348_piece0 in memory on localhost:38805 (size: 1850.0 B, free: 1918.5 MiB)
18:31:41.633 INFO  SparkContext - Created broadcast 1348 from broadcast at BamSink.java:76
18:31:41.635 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:31:41.635 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:31:41.635 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:31:41.648 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:31:41.649 INFO  DAGScheduler - Registering RDD 3420 (mapToPair at SparkUtils.java:161) as input to shuffle 101
18:31:41.649 INFO  DAGScheduler - Got job 415 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:31:41.649 INFO  DAGScheduler - Final stage: ResultStage 731 (runJob at SparkHadoopWriter.scala:83)
18:31:41.649 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 730)
18:31:41.649 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 730)
18:31:41.650 INFO  DAGScheduler - Submitting ShuffleMapStage 730 (MapPartitionsRDD[3420] at mapToPair at SparkUtils.java:161), which has no missing parents
18:31:41.651 INFO  MemoryStore - Block broadcast_1349 stored as values in memory (estimated size 18.1 KiB, free 1897.6 MiB)
18:31:41.651 INFO  MemoryStore - Block broadcast_1349_piece0 stored as bytes in memory (estimated size 9.5 KiB, free 1897.6 MiB)
18:31:41.651 INFO  BlockManagerInfo - Added broadcast_1349_piece0 in memory on localhost:38805 (size: 9.5 KiB, free: 1918.5 MiB)
18:31:41.652 INFO  SparkContext - Created broadcast 1349 from broadcast at DAGScheduler.scala:1580
18:31:41.652 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 730 (MapPartitionsRDD[3420] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:31:41.652 INFO  TaskSchedulerImpl - Adding task set 730.0 with 1 tasks resource profile 0
18:31:41.653 INFO  TaskSetManager - Starting task 0.0 in stage 730.0 (TID 656) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:31:41.653 INFO  Executor - Running task 0.0 in stage 730.0 (TID 656)
18:31:41.655 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.655 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.658 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.658 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.659 INFO  Executor - Finished task 0.0 in stage 730.0 (TID 656). 1922 bytes result sent to driver
18:31:41.660 INFO  TaskSetManager - Finished task 0.0 in stage 730.0 (TID 656) in 8 ms on localhost (executor driver) (1/1)
18:31:41.660 INFO  TaskSchedulerImpl - Removed TaskSet 730.0, whose tasks have all completed, from pool 
18:31:41.660 INFO  DAGScheduler - ShuffleMapStage 730 (mapToPair at SparkUtils.java:161) finished in 0.010 s
18:31:41.660 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.660 INFO  DAGScheduler - running: HashSet()
18:31:41.660 INFO  DAGScheduler - waiting: HashSet(ResultStage 731)
18:31:41.660 INFO  DAGScheduler - failed: HashSet()
18:31:41.660 INFO  DAGScheduler - Submitting ResultStage 731 (MapPartitionsRDD[3425] at mapToPair at BamSink.java:91), which has no missing parents
18:31:41.673 INFO  MemoryStore - Block broadcast_1350 stored as values in memory (estimated size 163.3 KiB, free 1897.5 MiB)
18:31:41.673 INFO  BlockManagerInfo - Removed broadcast_1346_piece0 on localhost:38805 in memory (size: 10.6 KiB, free: 1918.5 MiB)
18:31:41.674 INFO  BlockManagerInfo - Removed broadcast_1339_piece0 on localhost:38805 in memory (size: 201.4 KiB, free: 1918.7 MiB)
18:31:41.675 INFO  BlockManagerInfo - Removed broadcast_1330_piece0 on localhost:38805 in memory (size: 20.0 B, free: 1918.7 MiB)
18:31:41.675 INFO  MemoryStore - Block broadcast_1350_piece0 stored as bytes in memory (estimated size 73.4 KiB, free 1898.0 MiB)
18:31:41.675 INFO  BlockManagerInfo - Added broadcast_1350_piece0 in memory on localhost:38805 (size: 73.4 KiB, free: 1918.6 MiB)
18:31:41.675 INFO  SparkContext - Created broadcast 1350 from broadcast at DAGScheduler.scala:1580
18:31:41.675 INFO  BlockManagerInfo - Removed broadcast_1331_piece0 on localhost:38805 in memory (size: 228.2 KiB, free: 1918.8 MiB)
18:31:41.676 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 731 (MapPartitionsRDD[3425] at mapToPair at BamSink.java:91) (first 15 tasks are for partitions Vector(0))
18:31:41.676 INFO  TaskSchedulerImpl - Adding task set 731.0 with 1 tasks resource profile 0
18:31:41.676 INFO  BlockManagerInfo - Removed broadcast_1332_piece0 on localhost:38805 in memory (size: 228.2 KiB, free: 1919.1 MiB)
18:31:41.676 INFO  TaskSetManager - Starting task 0.0 in stage 731.0 (TID 657) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:31:41.677 INFO  Executor - Running task 0.0 in stage 731.0 (TID 657)
18:31:41.677 INFO  BlockManagerInfo - Removed broadcast_1336_piece0 on localhost:38805 in memory (size: 323.5 KiB, free: 1919.4 MiB)
18:31:41.677 INFO  BlockManagerInfo - Removed broadcast_1327_piece0 on localhost:38805 in memory (size: 64.1 KiB, free: 1919.4 MiB)
18:31:41.677 INFO  BlockManagerInfo - Removed broadcast_1343_piece0 on localhost:38805 in memory (size: 12.6 KiB, free: 1919.5 MiB)
18:31:41.678 INFO  BlockManagerInfo - Removed broadcast_1344_piece0 on localhost:38805 in memory (size: 14.8 KiB, free: 1919.5 MiB)
18:31:41.678 INFO  BlockManagerInfo - Removed broadcast_1340_piece0 on localhost:38805 in memory (size: 4.1 KiB, free: 1919.5 MiB)
18:31:41.679 INFO  BlockManagerInfo - Removed broadcast_1329_piece0 on localhost:38805 in memory (size: 19.0 B, free: 1919.5 MiB)
18:31:41.679 INFO  BlockManagerInfo - Removed broadcast_1345_piece0 on localhost:38805 in memory (size: 9.7 KiB, free: 1919.5 MiB)
18:31:41.680 INFO  BlockManagerInfo - Removed broadcast_1337_piece0 on localhost:38805 in memory (size: 64.0 KiB, free: 1919.5 MiB)
18:31:41.682 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.682 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.685 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:31:41.685 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:31:41.685 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:31:41.685 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:31:41.685 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:31:41.685 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:31:41.697 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271831418355886707598072243_3425_r_000000_0' to file:/tmp/local13803678826696211271/markdups4924698306019062034.bam.parts/_temporary/0/task_202505271831418355886707598072243_3425_r_000000
18:31:41.697 INFO  SparkHadoopMapRedUtil - attempt_202505271831418355886707598072243_3425_r_000000_0: Committed. Elapsed time: 0 ms.
18:31:41.698 INFO  Executor - Finished task 0.0 in stage 731.0 (TID 657). 1858 bytes result sent to driver
18:31:41.698 INFO  TaskSetManager - Finished task 0.0 in stage 731.0 (TID 657) in 22 ms on localhost (executor driver) (1/1)
18:31:41.699 INFO  TaskSchedulerImpl - Removed TaskSet 731.0, whose tasks have all completed, from pool 
18:31:41.699 INFO  DAGScheduler - ResultStage 731 (runJob at SparkHadoopWriter.scala:83) finished in 0.038 s
18:31:41.699 INFO  DAGScheduler - Job 415 is finished. Cancelling potential speculative or zombie tasks for this job
18:31:41.699 INFO  TaskSchedulerImpl - Killing all running tasks in stage 731: Stage finished
18:31:41.699 INFO  DAGScheduler - Job 415 finished: runJob at SparkHadoopWriter.scala:83, took 0.050758 s
18:31:41.699 INFO  SparkHadoopWriter - Start to commit write Job job_202505271831418355886707598072243_3425.
18:31:41.703 INFO  SparkHadoopWriter - Write Job job_202505271831418355886707598072243_3425 committed. Elapsed time: 3 ms.
18:31:41.714 INFO  HadoopFileSystemWrapper - Concatenating 3 parts to /tmp/local13803678826696211271/markdups4924698306019062034.bam
18:31:41.717 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/local13803678826696211271/markdups4924698306019062034.bam done
18:31:41.718 INFO  IndexFileMerger - Merging .sbi files in temp directory /tmp/local13803678826696211271/markdups4924698306019062034.bam.parts/ to /tmp/local13803678826696211271/markdups4924698306019062034.bam.sbi
18:31:41.721 INFO  IndexFileMerger - Done merging .sbi files
18:31:41.722 INFO  IndexFileMerger - Merging .bai files in temp directory /tmp/local13803678826696211271/markdups4924698306019062034.bam.parts/ to /tmp/local13803678826696211271/markdups4924698306019062034.bam.bai
18:31:41.726 INFO  IndexFileMerger - Done merging .bai files
18:31:41.726 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:31:41 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
18:31:41.744 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:31:41.745 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) v06789f4-SNAPSHOT
18:31:41.745 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:31:41.745 INFO  MarkDuplicatesSpark - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:31:41.745 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:31:41.745 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:31:41 PM GMT
18:31:41.745 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:31:41.745 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:31:41.745 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:31:41.745 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
18:31:41.745 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
18:31:41.745 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:31:41.745 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:31:41.745 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:31:41.745 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:31:41.745 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:31:41.745 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:31:41.745 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:31:41.746 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:31:41.746 INFO  MarkDuplicatesSpark - Initializing engine
18:31:41.746 INFO  MarkDuplicatesSpark - Done initializing engine
18:31:41.746 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:31:41.748 INFO  MemoryStore - Block broadcast_1351 stored as values in memory (estimated size 305.5 KiB, free 1913.8 MiB)
18:31:41.755 INFO  MemoryStore - Block broadcast_1351_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1913.8 MiB)
18:31:41.756 INFO  BlockManagerInfo - Added broadcast_1351_piece0 in memory on localhost:38805 (size: 64.0 KiB, free: 1919.5 MiB)
18:31:41.756 INFO  SparkContext - Created broadcast 1351 from newAPIHadoopFile at PathSplitSource.java:96
18:31:41.778 INFO  MemoryStore - Block broadcast_1352 stored as values in memory (estimated size 305.5 KiB, free 1913.5 MiB)
18:31:41.785 INFO  MemoryStore - Block broadcast_1352_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1913.4 MiB)
18:31:41.785 INFO  BlockManagerInfo - Added broadcast_1352_piece0 in memory on localhost:38805 (size: 64.0 KiB, free: 1919.4 MiB)
18:31:41.786 INFO  SparkContext - Created broadcast 1352 from newAPIHadoopFile at PathSplitSource.java:96
18:31:41.822 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:31:41.823 INFO  FileInputFormat - Total input files to process : 1
18:31:41.823 INFO  DAGScheduler - Registering RDD 3439 (mapToPair at SparkUtils.java:161) as input to shuffle 102
18:31:41.824 INFO  DAGScheduler - Got job 416 (collect at SparkUtils.java:205) with 1 output partitions
18:31:41.824 INFO  DAGScheduler - Final stage: ResultStage 733 (collect at SparkUtils.java:205)
18:31:41.824 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 732)
18:31:41.824 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 732)
18:31:41.824 INFO  DAGScheduler - Submitting ShuffleMapStage 732 (MapPartitionsRDD[3439] at mapToPair at SparkUtils.java:161), which has no missing parents
18:31:41.842 INFO  MemoryStore - Block broadcast_1353 stored as values in memory (estimated size 459.2 KiB, free 1913.0 MiB)
18:31:41.845 INFO  MemoryStore - Block broadcast_1353_piece0 stored as bytes in memory (estimated size 201.4 KiB, free 1912.8 MiB)
18:31:41.845 INFO  BlockManagerInfo - Added broadcast_1353_piece0 in memory on localhost:38805 (size: 201.4 KiB, free: 1919.2 MiB)
18:31:41.845 INFO  SparkContext - Created broadcast 1353 from broadcast at DAGScheduler.scala:1580
18:31:41.846 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 732 (MapPartitionsRDD[3439] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:31:41.846 INFO  TaskSchedulerImpl - Adding task set 732.0 with 1 tasks resource profile 0
18:31:41.847 INFO  TaskSetManager - Starting task 0.0 in stage 732.0 (TID 658) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9651 bytes) 
18:31:41.847 INFO  Executor - Running task 0.0 in stage 732.0 (TID 658)
18:31:41.886 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug2.bam:0+1856
18:31:41.892 INFO  Executor - Finished task 0.0 in stage 732.0 (TID 658). 1148 bytes result sent to driver
18:31:41.892 INFO  TaskSetManager - Finished task 0.0 in stage 732.0 (TID 658) in 46 ms on localhost (executor driver) (1/1)
18:31:41.892 INFO  TaskSchedulerImpl - Removed TaskSet 732.0, whose tasks have all completed, from pool 
18:31:41.893 INFO  DAGScheduler - ShuffleMapStage 732 (mapToPair at SparkUtils.java:161) finished in 0.069 s
18:31:41.893 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.893 INFO  DAGScheduler - running: HashSet()
18:31:41.893 INFO  DAGScheduler - waiting: HashSet(ResultStage 733)
18:31:41.893 INFO  DAGScheduler - failed: HashSet()
18:31:41.893 INFO  DAGScheduler - Submitting ResultStage 733 (MapPartitionsRDD[3442] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:31:41.894 INFO  MemoryStore - Block broadcast_1354 stored as values in memory (estimated size 7.4 KiB, free 1912.8 MiB)
18:31:41.895 INFO  MemoryStore - Block broadcast_1354_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1912.8 MiB)
18:31:41.895 INFO  BlockManagerInfo - Added broadcast_1354_piece0 in memory on localhost:38805 (size: 4.1 KiB, free: 1919.2 MiB)
18:31:41.895 INFO  SparkContext - Created broadcast 1354 from broadcast at DAGScheduler.scala:1580
18:31:41.895 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 733 (MapPartitionsRDD[3442] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:31:41.895 INFO  TaskSchedulerImpl - Adding task set 733.0 with 1 tasks resource profile 0
18:31:41.896 INFO  TaskSetManager - Starting task 0.0 in stage 733.0 (TID 659) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:31:41.896 INFO  Executor - Running task 0.0 in stage 733.0 (TID 659)
18:31:41.898 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.898 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.900 INFO  Executor - Finished task 0.0 in stage 733.0 (TID 659). 2495 bytes result sent to driver
18:31:41.901 INFO  TaskSetManager - Finished task 0.0 in stage 733.0 (TID 659) in 5 ms on localhost (executor driver) (1/1)
18:31:41.901 INFO  TaskSchedulerImpl - Removed TaskSet 733.0, whose tasks have all completed, from pool 
18:31:41.901 INFO  DAGScheduler - ResultStage 733 (collect at SparkUtils.java:205) finished in 0.007 s
18:31:41.901 INFO  DAGScheduler - Job 416 is finished. Cancelling potential speculative or zombie tasks for this job
18:31:41.901 INFO  TaskSchedulerImpl - Killing all running tasks in stage 733: Stage finished
18:31:41.902 INFO  DAGScheduler - Job 416 finished: collect at SparkUtils.java:205, took 0.079657 s
18:31:41.906 INFO  MemoryStore - Block broadcast_1355 stored as values in memory (estimated size 1632.0 B, free 1912.8 MiB)
18:31:41.907 INFO  MemoryStore - Block broadcast_1355_piece0 stored as bytes in memory (estimated size 145.0 B, free 1912.8 MiB)
18:31:41.907 INFO  BlockManagerInfo - Added broadcast_1355_piece0 in memory on localhost:38805 (size: 145.0 B, free: 1919.2 MiB)
18:31:41.908 INFO  SparkContext - Created broadcast 1355 from broadcast at MarkDuplicatesSparkUtils.java:126
18:31:41.908 INFO  MemoryStore - Block broadcast_1356 stored as values in memory (estimated size 304.0 B, free 1912.8 MiB)
18:31:41.908 INFO  MemoryStore - Block broadcast_1356_piece0 stored as bytes in memory (estimated size 37.0 B, free 1912.8 MiB)
18:31:41.909 INFO  BlockManagerInfo - Added broadcast_1356_piece0 in memory on localhost:38805 (size: 37.0 B, free: 1919.2 MiB)
18:31:41.909 INFO  SparkContext - Created broadcast 1356 from broadcast at MarkDuplicatesSparkUtils.java:127
18:31:41.922 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:31:41.923 INFO  DAGScheduler - Registering RDD 3451 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 105
18:31:41.923 INFO  DAGScheduler - Registering RDD 3455 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 104
18:31:41.923 INFO  DAGScheduler - Registering RDD 3459 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 103
18:31:41.923 INFO  DAGScheduler - Got job 417 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:31:41.923 INFO  DAGScheduler - Final stage: ResultStage 738 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:31:41.924 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 737)
18:31:41.924 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 737)
18:31:41.924 INFO  DAGScheduler - Submitting ShuffleMapStage 735 (MapPartitionsRDD[3451] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:31:41.925 INFO  MemoryStore - Block broadcast_1357 stored as values in memory (estimated size 24.2 KiB, free 1912.7 MiB)
18:31:41.925 INFO  MemoryStore - Block broadcast_1357_piece0 stored as bytes in memory (estimated size 12.6 KiB, free 1912.7 MiB)
18:31:41.926 INFO  BlockManagerInfo - Added broadcast_1357_piece0 in memory on localhost:38805 (size: 12.6 KiB, free: 1919.2 MiB)
18:31:41.926 INFO  SparkContext - Created broadcast 1357 from broadcast at DAGScheduler.scala:1580
18:31:41.926 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 735 (MapPartitionsRDD[3451] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:31:41.926 INFO  TaskSchedulerImpl - Adding task set 735.0 with 1 tasks resource profile 0
18:31:41.927 INFO  TaskSetManager - Starting task 0.0 in stage 735.0 (TID 660) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
18:31:41.927 INFO  Executor - Running task 0.0 in stage 735.0 (TID 660)
18:31:41.929 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.930 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.934 INFO  Executor - Finished task 0.0 in stage 735.0 (TID 660). 1922 bytes result sent to driver
18:31:41.934 INFO  TaskSetManager - Finished task 0.0 in stage 735.0 (TID 660) in 7 ms on localhost (executor driver) (1/1)
18:31:41.934 INFO  TaskSchedulerImpl - Removed TaskSet 735.0, whose tasks have all completed, from pool 
18:31:41.935 INFO  DAGScheduler - ShuffleMapStage 735 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.010 s
18:31:41.935 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.935 INFO  DAGScheduler - running: HashSet()
18:31:41.935 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 736, ShuffleMapStage 737, ResultStage 738)
18:31:41.935 INFO  DAGScheduler - failed: HashSet()
18:31:41.935 INFO  DAGScheduler - Submitting ShuffleMapStage 736 (MapPartitionsRDD[3455] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:31:41.936 INFO  MemoryStore - Block broadcast_1358 stored as values in memory (estimated size 28.3 KiB, free 1912.7 MiB)
18:31:41.937 INFO  MemoryStore - Block broadcast_1358_piece0 stored as bytes in memory (estimated size 14.8 KiB, free 1912.7 MiB)
18:31:41.937 INFO  BlockManagerInfo - Added broadcast_1358_piece0 in memory on localhost:38805 (size: 14.8 KiB, free: 1919.2 MiB)
18:31:41.937 INFO  SparkContext - Created broadcast 1358 from broadcast at DAGScheduler.scala:1580
18:31:41.937 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 736 (MapPartitionsRDD[3455] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:31:41.937 INFO  TaskSchedulerImpl - Adding task set 736.0 with 1 tasks resource profile 0
18:31:41.938 INFO  TaskSetManager - Starting task 0.0 in stage 736.0 (TID 661) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
18:31:41.938 INFO  Executor - Running task 0.0 in stage 736.0 (TID 661)
18:31:41.940 INFO  ShuffleBlockFetcherIterator - Getting 1 (142.0 B) non-empty blocks including 1 (142.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.940 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.945 INFO  Executor - Finished task 0.0 in stage 736.0 (TID 661). 1922 bytes result sent to driver
18:31:41.945 INFO  TaskSetManager - Finished task 0.0 in stage 736.0 (TID 661) in 7 ms on localhost (executor driver) (1/1)
18:31:41.945 INFO  TaskSchedulerImpl - Removed TaskSet 736.0, whose tasks have all completed, from pool 
18:31:41.945 INFO  DAGScheduler - ShuffleMapStage 736 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.010 s
18:31:41.946 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.946 INFO  DAGScheduler - running: HashSet()
18:31:41.946 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 737, ResultStage 738)
18:31:41.946 INFO  DAGScheduler - failed: HashSet()
18:31:41.946 INFO  DAGScheduler - Submitting ShuffleMapStage 737 (MapPartitionsRDD[3459] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:31:41.947 INFO  MemoryStore - Block broadcast_1359 stored as values in memory (estimated size 19.0 KiB, free 1912.7 MiB)
18:31:41.947 INFO  MemoryStore - Block broadcast_1359_piece0 stored as bytes in memory (estimated size 9.7 KiB, free 1912.7 MiB)
18:31:41.948 INFO  BlockManagerInfo - Added broadcast_1359_piece0 in memory on localhost:38805 (size: 9.7 KiB, free: 1919.2 MiB)
18:31:41.948 INFO  SparkContext - Created broadcast 1359 from broadcast at DAGScheduler.scala:1580
18:31:41.948 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 737 (MapPartitionsRDD[3459] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:31:41.948 INFO  TaskSchedulerImpl - Adding task set 737.0 with 1 tasks resource profile 0
18:31:41.949 INFO  TaskSetManager - Starting task 0.0 in stage 737.0 (TID 662) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:31:41.949 INFO  Executor - Running task 0.0 in stage 737.0 (TID 662)
18:31:41.951 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.951 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.954 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.954 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.956 INFO  Executor - Finished task 0.0 in stage 737.0 (TID 662). 1922 bytes result sent to driver
18:31:41.956 INFO  TaskSetManager - Finished task 0.0 in stage 737.0 (TID 662) in 8 ms on localhost (executor driver) (1/1)
18:31:41.956 INFO  TaskSchedulerImpl - Removed TaskSet 737.0, whose tasks have all completed, from pool 
18:31:41.956 INFO  DAGScheduler - ShuffleMapStage 737 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.010 s
18:31:41.956 INFO  DAGScheduler - looking for newly runnable stages
18:31:41.956 INFO  DAGScheduler - running: HashSet()
18:31:41.956 INFO  DAGScheduler - waiting: HashSet(ResultStage 738)
18:31:41.957 INFO  DAGScheduler - failed: HashSet()
18:31:41.957 INFO  DAGScheduler - Submitting ResultStage 738 (MapPartitionsRDD[3461] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:31:41.958 INFO  MemoryStore - Block broadcast_1360 stored as values in memory (estimated size 20.2 KiB, free 1912.6 MiB)
18:31:41.959 INFO  MemoryStore - Block broadcast_1360_piece0 stored as bytes in memory (estimated size 10.6 KiB, free 1912.6 MiB)
18:31:41.959 INFO  BlockManagerInfo - Added broadcast_1360_piece0 in memory on localhost:38805 (size: 10.6 KiB, free: 1919.2 MiB)
18:31:41.959 INFO  SparkContext - Created broadcast 1360 from broadcast at DAGScheduler.scala:1580
18:31:41.959 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 738 (MapPartitionsRDD[3461] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:31:41.959 INFO  TaskSchedulerImpl - Adding task set 738.0 with 1 tasks resource profile 0
18:31:41.960 INFO  TaskSetManager - Starting task 0.0 in stage 738.0 (TID 663) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:31:41.960 INFO  Executor - Running task 0.0 in stage 738.0 (TID 663)
18:31:41.962 INFO  ShuffleBlockFetcherIterator - Getting 1 (142.0 B) non-empty blocks including 1 (142.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:41.962 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:41.965 INFO  Executor - Finished task 0.0 in stage 738.0 (TID 663). 2053 bytes result sent to driver
18:31:41.966 INFO  TaskSetManager - Finished task 0.0 in stage 738.0 (TID 663) in 6 ms on localhost (executor driver) (1/1)
18:31:41.966 INFO  TaskSchedulerImpl - Removed TaskSet 738.0, whose tasks have all completed, from pool 
18:31:41.966 INFO  DAGScheduler - ResultStage 738 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.009 s
18:31:41.966 INFO  DAGScheduler - Job 417 is finished. Cancelling potential speculative or zombie tasks for this job
18:31:41.966 INFO  TaskSchedulerImpl - Killing all running tasks in stage 738: Stage finished
18:31:41.966 INFO  DAGScheduler - Job 417 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.043755 s
18:31:41.977 INFO  MemoryStore - Block broadcast_1361 stored as values in memory (estimated size 20.3 KiB, free 1912.6 MiB)
18:31:41.978 INFO  MemoryStore - Block broadcast_1361_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1912.6 MiB)
18:31:41.978 INFO  BlockManagerInfo - Added broadcast_1361_piece0 in memory on localhost:38805 (size: 1850.0 B, free: 1919.2 MiB)
18:31:41.979 INFO  SparkContext - Created broadcast 1361 from broadcast at ReadsSparkSink.java:133
18:31:41.979 INFO  MemoryStore - Block broadcast_1362 stored as values in memory (estimated size 20.4 KiB, free 1912.6 MiB)
18:31:41.980 INFO  MemoryStore - Block broadcast_1362_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1912.6 MiB)
18:31:41.980 INFO  BlockManagerInfo - Added broadcast_1362_piece0 in memory on localhost:38805 (size: 1850.0 B, free: 1919.2 MiB)
18:31:41.981 INFO  SparkContext - Created broadcast 1362 from broadcast at BamSink.java:76
18:31:41.983 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:31:41.983 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:31:41.983 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:31:41.999 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:31:41.999 INFO  DAGScheduler - Registering RDD 3463 (mapToPair at SparkUtils.java:161) as input to shuffle 106
18:31:41.999 INFO  DAGScheduler - Got job 418 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:31:42.000 INFO  DAGScheduler - Final stage: ResultStage 743 (runJob at SparkHadoopWriter.scala:83)
18:31:42.000 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 742)
18:31:42.000 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 742)
18:31:42.000 INFO  DAGScheduler - Submitting ShuffleMapStage 742 (MapPartitionsRDD[3463] at mapToPair at SparkUtils.java:161), which has no missing parents
18:31:42.001 INFO  MemoryStore - Block broadcast_1363 stored as values in memory (estimated size 18.1 KiB, free 1912.6 MiB)
18:31:42.002 INFO  MemoryStore - Block broadcast_1363_piece0 stored as bytes in memory (estimated size 9.5 KiB, free 1912.6 MiB)
18:31:42.002 INFO  BlockManagerInfo - Added broadcast_1363_piece0 in memory on localhost:38805 (size: 9.5 KiB, free: 1919.2 MiB)
18:31:42.002 INFO  SparkContext - Created broadcast 1363 from broadcast at DAGScheduler.scala:1580
18:31:42.002 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 742 (MapPartitionsRDD[3463] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:31:42.002 INFO  TaskSchedulerImpl - Adding task set 742.0 with 1 tasks resource profile 0
18:31:42.003 INFO  TaskSetManager - Starting task 0.0 in stage 742.0 (TID 664) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:31:42.003 INFO  Executor - Running task 0.0 in stage 742.0 (TID 664)
18:31:42.005 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:42.005 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:42.008 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:42.008 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:42.010 INFO  Executor - Finished task 0.0 in stage 742.0 (TID 664). 1922 bytes result sent to driver
18:31:42.010 INFO  TaskSetManager - Finished task 0.0 in stage 742.0 (TID 664) in 7 ms on localhost (executor driver) (1/1)
18:31:42.010 INFO  TaskSchedulerImpl - Removed TaskSet 742.0, whose tasks have all completed, from pool 
18:31:42.010 INFO  DAGScheduler - ShuffleMapStage 742 (mapToPair at SparkUtils.java:161) finished in 0.010 s
18:31:42.010 INFO  DAGScheduler - looking for newly runnable stages
18:31:42.011 INFO  DAGScheduler - running: HashSet()
18:31:42.011 INFO  DAGScheduler - waiting: HashSet(ResultStage 743)
18:31:42.011 INFO  DAGScheduler - failed: HashSet()
18:31:42.011 INFO  DAGScheduler - Submitting ResultStage 743 (MapPartitionsRDD[3468] at mapToPair at BamSink.java:91), which has no missing parents
18:31:42.018 INFO  MemoryStore - Block broadcast_1364 stored as values in memory (estimated size 163.3 KiB, free 1912.4 MiB)
18:31:42.019 INFO  MemoryStore - Block broadcast_1364_piece0 stored as bytes in memory (estimated size 73.4 KiB, free 1912.3 MiB)
18:31:42.019 INFO  BlockManagerInfo - Added broadcast_1364_piece0 in memory on localhost:38805 (size: 73.4 KiB, free: 1919.1 MiB)
18:31:42.020 INFO  SparkContext - Created broadcast 1364 from broadcast at DAGScheduler.scala:1580
18:31:42.020 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 743 (MapPartitionsRDD[3468] at mapToPair at BamSink.java:91) (first 15 tasks are for partitions Vector(0))
18:31:42.020 INFO  TaskSchedulerImpl - Adding task set 743.0 with 1 tasks resource profile 0
18:31:42.020 INFO  TaskSetManager - Starting task 0.0 in stage 743.0 (TID 665) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:31:42.021 INFO  Executor - Running task 0.0 in stage 743.0 (TID 665)
18:31:42.025 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:31:42.025 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:31:42.028 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:31:42.028 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:31:42.028 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:31:42.028 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:31:42.028 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:31:42.028 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:31:42.042 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271831418554407118961150632_3468_r_000000_0' to file:/tmp/local13803678826696211271/markdups6083205045573053939.bam.parts/_temporary/0/task_202505271831418554407118961150632_3468_r_000000
18:31:42.043 INFO  SparkHadoopMapRedUtil - attempt_202505271831418554407118961150632_3468_r_000000_0: Committed. Elapsed time: 0 ms.
18:31:42.043 INFO  Executor - Finished task 0.0 in stage 743.0 (TID 665). 1858 bytes result sent to driver
18:31:42.044 INFO  TaskSetManager - Finished task 0.0 in stage 743.0 (TID 665) in 24 ms on localhost (executor driver) (1/1)
18:31:42.044 INFO  TaskSchedulerImpl - Removed TaskSet 743.0, whose tasks have all completed, from pool 
18:31:42.044 INFO  DAGScheduler - ResultStage 743 (runJob at SparkHadoopWriter.scala:83) finished in 0.033 s
18:31:42.044 INFO  DAGScheduler - Job 418 is finished. Cancelling potential speculative or zombie tasks for this job
18:31:42.044 INFO  TaskSchedulerImpl - Killing all running tasks in stage 743: Stage finished
18:31:42.045 INFO  DAGScheduler - Job 418 finished: runJob at SparkHadoopWriter.scala:83, took 0.045902 s
18:31:42.045 INFO  SparkHadoopWriter - Start to commit write Job job_202505271831418554407118961150632_3468.
18:31:42.049 INFO  SparkHadoopWriter - Write Job job_202505271831418554407118961150632_3468 committed. Elapsed time: 4 ms.
18:31:42.056 INFO  HadoopFileSystemWrapper - Concatenating 3 parts to /tmp/local13803678826696211271/markdups6083205045573053939.bam
18:31:42.059 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/local13803678826696211271/markdups6083205045573053939.bam done
18:31:42.059 INFO  IndexFileMerger - Merging .sbi files in temp directory /tmp/local13803678826696211271/markdups6083205045573053939.bam.parts/ to /tmp/local13803678826696211271/markdups6083205045573053939.bam.sbi
18:31:42.062 INFO  IndexFileMerger - Done merging .sbi files
18:31:42.063 INFO  IndexFileMerger - Merging .bai files in temp directory /tmp/local13803678826696211271/markdups6083205045573053939.bam.parts/ to /tmp/local13803678826696211271/markdups6083205045573053939.bam.bai
18:31:42.066 INFO  IndexFileMerger - Done merging .bai files
18:31:42.066 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:31:42 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:42 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:42 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:43 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:43 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:44 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:44 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:45 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:47 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:47 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:48 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:48 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:49 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:49 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:50 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:52 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:52 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:53 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:53 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:53 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:54 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:55 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:56 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:57 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:57 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:58 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:58 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:31:58 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:00 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:01 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:01 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:02 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:02 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:02 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:03 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:04 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:05 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:05 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:07 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:09 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:09 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
18:32:09.925 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:09.925 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) v06789f4-SNAPSHOT
18:32:09.925 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:32:09.925 INFO  MarkDuplicatesSpark - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:32:09.925 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:32:09.925 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:32:09 PM GMT
18:32:09.925 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:09.925 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:09.926 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:32:09.926 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
18:32:09.926 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
18:32:09.926 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:32:09.926 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:32:09.926 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:32:09.926 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:32:09.926 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:32:09.926 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:32:09.926 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:32:09.926 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:32:09.926 INFO  MarkDuplicatesSpark - Initializing engine
18:32:09.926 INFO  MarkDuplicatesSpark - Done initializing engine
18:32:09.926 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:32:09.929 INFO  MemoryStore - Block broadcast_1941 stored as values in memory (estimated size 305.5 KiB, free 1912.1 MiB)
18:32:09.936 INFO  MemoryStore - Block broadcast_1941_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1912.1 MiB)
18:32:09.936 INFO  BlockManagerInfo - Added broadcast_1941_piece0 in memory on localhost:38805 (size: 64.0 KiB, free: 1919.0 MiB)
18:32:09.937 INFO  SparkContext - Created broadcast 1941 from newAPIHadoopFile at PathSplitSource.java:96
18:32:09.960 INFO  MemoryStore - Block broadcast_1942 stored as values in memory (estimated size 305.5 KiB, free 1911.8 MiB)
18:32:09.967 INFO  MemoryStore - Block broadcast_1942_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1911.7 MiB)
18:32:09.967 INFO  BlockManagerInfo - Added broadcast_1942_piece0 in memory on localhost:38805 (size: 64.0 KiB, free: 1919.0 MiB)
18:32:09.968 INFO  SparkContext - Created broadcast 1942 from newAPIHadoopFile at PathSplitSource.java:96
18:32:10.007 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:32:10.008 INFO  FileInputFormat - Total input files to process : 1
18:32:10.009 INFO  DAGScheduler - Registering RDD 5360 (mapToPair at SparkUtils.java:161) as input to shuffle 297
18:32:10.009 INFO  DAGScheduler - Got job 549 (collect at SparkUtils.java:205) with 1 output partitions
18:32:10.009 INFO  DAGScheduler - Final stage: ResultStage 1205 (collect at SparkUtils.java:205)
18:32:10.009 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1204)
18:32:10.009 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1204)
18:32:10.009 INFO  DAGScheduler - Submitting ShuffleMapStage 1204 (MapPartitionsRDD[5360] at mapToPair at SparkUtils.java:161), which has no missing parents
18:32:10.029 INFO  MemoryStore - Block broadcast_1943 stored as values in memory (estimated size 492.6 KiB, free 1911.2 MiB)
18:32:10.032 INFO  MemoryStore - Block broadcast_1943_piece0 stored as bytes in memory (estimated size 208.9 KiB, free 1911.0 MiB)
18:32:10.032 INFO  BlockManagerInfo - Added broadcast_1943_piece0 in memory on localhost:38805 (size: 208.9 KiB, free: 1918.8 MiB)
18:32:10.033 INFO  SparkContext - Created broadcast 1943 from broadcast at DAGScheduler.scala:1580
18:32:10.033 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1204 (MapPartitionsRDD[5360] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:32:10.033 INFO  TaskSchedulerImpl - Adding task set 1204.0 with 1 tasks resource profile 0
18:32:10.033 INFO  TaskSetManager - Starting task 0.0 in stage 1204.0 (TID 1036) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9674 bytes) 
18:32:10.034 INFO  Executor - Running task 0.0 in stage 1204.0 (TID 1036)
18:32:10.074 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/example.chr1.1-1K.unmarkedDups.bam:0+13412
18:32:10.081 INFO  Executor - Finished task 0.0 in stage 1204.0 (TID 1036). 1148 bytes result sent to driver
18:32:10.082 INFO  TaskSetManager - Finished task 0.0 in stage 1204.0 (TID 1036) in 48 ms on localhost (executor driver) (1/1)
18:32:10.082 INFO  TaskSchedulerImpl - Removed TaskSet 1204.0, whose tasks have all completed, from pool 
18:32:10.082 INFO  DAGScheduler - ShuffleMapStage 1204 (mapToPair at SparkUtils.java:161) finished in 0.072 s
18:32:10.082 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.082 INFO  DAGScheduler - running: HashSet()
18:32:10.082 INFO  DAGScheduler - waiting: HashSet(ResultStage 1205)
18:32:10.082 INFO  DAGScheduler - failed: HashSet()
18:32:10.082 INFO  DAGScheduler - Submitting ResultStage 1205 (MapPartitionsRDD[5363] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:32:10.083 INFO  MemoryStore - Block broadcast_1944 stored as values in memory (estimated size 7.4 KiB, free 1911.0 MiB)
18:32:10.083 INFO  MemoryStore - Block broadcast_1944_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1911.0 MiB)
18:32:10.084 INFO  BlockManagerInfo - Added broadcast_1944_piece0 in memory on localhost:38805 (size: 4.1 KiB, free: 1918.8 MiB)
18:32:10.084 INFO  SparkContext - Created broadcast 1944 from broadcast at DAGScheduler.scala:1580
18:32:10.084 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1205 (MapPartitionsRDD[5363] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:32:10.084 INFO  TaskSchedulerImpl - Adding task set 1205.0 with 1 tasks resource profile 0
18:32:10.085 INFO  TaskSetManager - Starting task 0.0 in stage 1205.0 (TID 1037) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.085 INFO  Executor - Running task 0.0 in stage 1205.0 (TID 1037)
18:32:10.087 INFO  ShuffleBlockFetcherIterator - Getting 1 (16.3 KiB) non-empty blocks including 1 (16.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.087 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.091 INFO  Executor - Finished task 0.0 in stage 1205.0 (TID 1037). 2372 bytes result sent to driver
18:32:10.092 INFO  TaskSetManager - Finished task 0.0 in stage 1205.0 (TID 1037) in 8 ms on localhost (executor driver) (1/1)
18:32:10.092 INFO  TaskSchedulerImpl - Removed TaskSet 1205.0, whose tasks have all completed, from pool 
18:32:10.092 INFO  DAGScheduler - ResultStage 1205 (collect at SparkUtils.java:205) finished in 0.010 s
18:32:10.092 INFO  DAGScheduler - Job 549 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.092 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1205: Stage finished
18:32:10.092 INFO  DAGScheduler - Job 549 finished: collect at SparkUtils.java:205, took 0.084765 s
18:32:10.098 INFO  MemoryStore - Block broadcast_1945 stored as values in memory (estimated size 7.8 KiB, free 1911.0 MiB)
18:32:10.099 INFO  MemoryStore - Block broadcast_1945_piece0 stored as bytes in memory (estimated size 540.0 B, free 1911.0 MiB)
18:32:10.099 INFO  BlockManagerInfo - Added broadcast_1945_piece0 in memory on localhost:38805 (size: 540.0 B, free: 1918.8 MiB)
18:32:10.100 INFO  SparkContext - Created broadcast 1945 from broadcast at MarkDuplicatesSparkUtils.java:126
18:32:10.100 INFO  MemoryStore - Block broadcast_1946 stored as values in memory (estimated size 2.6 KiB, free 1911.0 MiB)
18:32:10.100 INFO  MemoryStore - Block broadcast_1946_piece0 stored as bytes in memory (estimated size 209.0 B, free 1911.0 MiB)
18:32:10.101 INFO  BlockManagerInfo - Added broadcast_1946_piece0 in memory on localhost:38805 (size: 209.0 B, free: 1918.8 MiB)
18:32:10.101 INFO  SparkContext - Created broadcast 1946 from broadcast at MarkDuplicatesSparkUtils.java:127
18:32:10.118 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:32:10.119 INFO  DAGScheduler - Registering RDD 5372 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 300
18:32:10.119 INFO  DAGScheduler - Registering RDD 5376 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 299
18:32:10.119 INFO  DAGScheduler - Registering RDD 5380 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 298
18:32:10.119 INFO  DAGScheduler - Got job 550 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:32:10.119 INFO  DAGScheduler - Final stage: ResultStage 1210 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:32:10.119 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1209)
18:32:10.119 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1209)
18:32:10.120 INFO  DAGScheduler - Submitting ShuffleMapStage 1207 (MapPartitionsRDD[5372] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:32:10.122 INFO  MemoryStore - Block broadcast_1947 stored as values in memory (estimated size 57.6 KiB, free 1910.9 MiB)
18:32:10.123 INFO  MemoryStore - Block broadcast_1947_piece0 stored as bytes in memory (estimated size 19.8 KiB, free 1910.9 MiB)
18:32:10.123 INFO  BlockManagerInfo - Added broadcast_1947_piece0 in memory on localhost:38805 (size: 19.8 KiB, free: 1918.7 MiB)
18:32:10.123 INFO  SparkContext - Created broadcast 1947 from broadcast at DAGScheduler.scala:1580
18:32:10.124 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1207 (MapPartitionsRDD[5372] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:32:10.124 INFO  TaskSchedulerImpl - Adding task set 1207.0 with 1 tasks resource profile 0
18:32:10.125 INFO  TaskSetManager - Starting task 0.0 in stage 1207.0 (TID 1038) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
18:32:10.125 INFO  Executor - Running task 0.0 in stage 1207.0 (TID 1038)
18:32:10.128 INFO  ShuffleBlockFetcherIterator - Getting 1 (16.3 KiB) non-empty blocks including 1 (16.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.128 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.133 INFO  Executor - Finished task 0.0 in stage 1207.0 (TID 1038). 1922 bytes result sent to driver
18:32:10.134 INFO  TaskSetManager - Finished task 0.0 in stage 1207.0 (TID 1038) in 10 ms on localhost (executor driver) (1/1)
18:32:10.134 INFO  TaskSchedulerImpl - Removed TaskSet 1207.0, whose tasks have all completed, from pool 
18:32:10.134 INFO  DAGScheduler - ShuffleMapStage 1207 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.014 s
18:32:10.135 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.135 INFO  DAGScheduler - running: HashSet()
18:32:10.135 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1208, ShuffleMapStage 1209, ResultStage 1210)
18:32:10.135 INFO  DAGScheduler - failed: HashSet()
18:32:10.135 INFO  DAGScheduler - Submitting ShuffleMapStage 1208 (MapPartitionsRDD[5376] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:32:10.137 INFO  MemoryStore - Block broadcast_1948 stored as values in memory (estimated size 61.7 KiB, free 1910.8 MiB)
18:32:10.138 INFO  MemoryStore - Block broadcast_1948_piece0 stored as bytes in memory (estimated size 22.0 KiB, free 1910.8 MiB)
18:32:10.138 INFO  BlockManagerInfo - Added broadcast_1948_piece0 in memory on localhost:38805 (size: 22.0 KiB, free: 1918.7 MiB)
18:32:10.138 INFO  SparkContext - Created broadcast 1948 from broadcast at DAGScheduler.scala:1580
18:32:10.138 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1208 (MapPartitionsRDD[5376] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:32:10.138 INFO  TaskSchedulerImpl - Adding task set 1208.0 with 1 tasks resource profile 0
18:32:10.139 INFO  TaskSetManager - Starting task 0.0 in stage 1208.0 (TID 1039) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
18:32:10.139 INFO  Executor - Running task 0.0 in stage 1208.0 (TID 1039)
18:32:10.142 INFO  ShuffleBlockFetcherIterator - Getting 1 (2.0 KiB) non-empty blocks including 1 (2.0 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.142 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.148 INFO  Executor - Finished task 0.0 in stage 1208.0 (TID 1039). 1922 bytes result sent to driver
18:32:10.149 INFO  TaskSetManager - Finished task 0.0 in stage 1208.0 (TID 1039) in 10 ms on localhost (executor driver) (1/1)
18:32:10.149 INFO  TaskSchedulerImpl - Removed TaskSet 1208.0, whose tasks have all completed, from pool 
18:32:10.149 INFO  DAGScheduler - ShuffleMapStage 1208 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.014 s
18:32:10.149 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.149 INFO  DAGScheduler - running: HashSet()
18:32:10.149 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1209, ResultStage 1210)
18:32:10.149 INFO  DAGScheduler - failed: HashSet()
18:32:10.149 INFO  DAGScheduler - Submitting ShuffleMapStage 1209 (MapPartitionsRDD[5380] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:32:10.151 INFO  MemoryStore - Block broadcast_1949 stored as values in memory (estimated size 52.4 KiB, free 1910.8 MiB)
18:32:10.152 INFO  MemoryStore - Block broadcast_1949_piece0 stored as bytes in memory (estimated size 17.3 KiB, free 1910.8 MiB)
18:32:10.152 INFO  BlockManagerInfo - Added broadcast_1949_piece0 in memory on localhost:38805 (size: 17.3 KiB, free: 1918.7 MiB)
18:32:10.152 INFO  SparkContext - Created broadcast 1949 from broadcast at DAGScheduler.scala:1580
18:32:10.153 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1209 (MapPartitionsRDD[5380] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:32:10.153 INFO  TaskSchedulerImpl - Adding task set 1209.0 with 1 tasks resource profile 0
18:32:10.153 INFO  TaskSetManager - Starting task 0.0 in stage 1209.0 (TID 1040) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:32:10.154 INFO  Executor - Running task 0.0 in stage 1209.0 (TID 1040)
18:32:10.156 INFO  ShuffleBlockFetcherIterator - Getting 1 (16.3 KiB) non-empty blocks including 1 (16.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.156 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.159 INFO  ShuffleBlockFetcherIterator - Getting 1 (2.7 KiB) non-empty blocks including 1 (2.7 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.159 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.167 INFO  Executor - Finished task 0.0 in stage 1209.0 (TID 1040). 2008 bytes result sent to driver
18:32:10.167 INFO  BlockManagerInfo - Removed broadcast_1929_piece0 on localhost:38805 in memory (size: 64.0 KiB, free: 1918.8 MiB)
18:32:10.168 INFO  TaskSetManager - Finished task 0.0 in stage 1209.0 (TID 1040) in 15 ms on localhost (executor driver) (1/1)
18:32:10.168 INFO  BlockManagerInfo - Removed broadcast_1941_piece0 on localhost:38805 in memory (size: 64.0 KiB, free: 1918.8 MiB)
18:32:10.168 INFO  TaskSchedulerImpl - Removed TaskSet 1209.0, whose tasks have all completed, from pool 
18:32:10.169 INFO  DAGScheduler - ShuffleMapStage 1209 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.018 s
18:32:10.169 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.169 INFO  DAGScheduler - running: HashSet()
18:32:10.169 INFO  DAGScheduler - waiting: HashSet(ResultStage 1210)
18:32:10.169 INFO  DAGScheduler - failed: HashSet()
18:32:10.169 INFO  DAGScheduler - Submitting ResultStage 1210 (MapPartitionsRDD[5382] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:32:10.169 INFO  BlockManagerInfo - Removed broadcast_1925_piece0 on localhost:38805 in memory (size: 663.0 B, free: 1918.8 MiB)
18:32:10.170 INFO  BlockManagerInfo - Removed broadcast_1943_piece0 on localhost:38805 in memory (size: 208.9 KiB, free: 1919.0 MiB)
18:32:10.170 INFO  BlockManagerInfo - Removed broadcast_1935_piece0 on localhost:38805 in memory (size: 13.2 KiB, free: 1919.1 MiB)
18:32:10.171 INFO  MemoryStore - Block broadcast_1950 stored as values in memory (estimated size 53.6 KiB, free 1912.2 MiB)
18:32:10.171 INFO  BlockManagerInfo - Removed broadcast_1930_piece0 on localhost:38805 in memory (size: 200.3 KiB, free: 1919.2 MiB)
18:32:10.171 INFO  BlockManagerInfo - Removed broadcast_1947_piece0 on localhost:38805 in memory (size: 19.8 KiB, free: 1919.3 MiB)
18:32:10.172 INFO  MemoryStore - Block broadcast_1950_piece0 stored as bytes in memory (estimated size 18.0 KiB, free 1912.9 MiB)
18:32:10.172 INFO  BlockManagerInfo - Removed broadcast_1934_piece0 on localhost:38805 in memory (size: 11.2 KiB, free: 1919.3 MiB)
18:32:10.172 INFO  BlockManagerInfo - Added broadcast_1950_piece0 in memory on localhost:38805 (size: 18.0 KiB, free: 1919.3 MiB)
18:32:10.172 INFO  BlockManagerInfo - Removed broadcast_1937_piece0 on localhost:38805 in memory (size: 9.1 KiB, free: 1919.3 MiB)
18:32:10.172 INFO  SparkContext - Created broadcast 1950 from broadcast at DAGScheduler.scala:1580
18:32:10.172 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1210 (MapPartitionsRDD[5382] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:32:10.172 INFO  TaskSchedulerImpl - Adding task set 1210.0 with 1 tasks resource profile 0
18:32:10.172 INFO  BlockManagerInfo - Removed broadcast_1932_piece0 on localhost:38805 in memory (size: 19.0 B, free: 1919.3 MiB)
18:32:10.173 INFO  BlockManagerInfo - Removed broadcast_1931_piece0 on localhost:38805 in memory (size: 4.1 KiB, free: 1919.3 MiB)
18:32:10.173 INFO  TaskSetManager - Starting task 0.0 in stage 1210.0 (TID 1041) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.173 INFO  Executor - Running task 0.0 in stage 1210.0 (TID 1041)
18:32:10.173 INFO  BlockManagerInfo - Removed broadcast_1933_piece0 on localhost:38805 in memory (size: 31.0 B, free: 1919.3 MiB)
18:32:10.174 INFO  BlockManagerInfo - Removed broadcast_1938_piece0 on localhost:38805 in memory (size: 663.0 B, free: 1919.3 MiB)
18:32:10.174 INFO  BlockManagerInfo - Removed broadcast_1944_piece0 on localhost:38805 in memory (size: 4.1 KiB, free: 1919.3 MiB)
18:32:10.175 INFO  BlockManagerInfo - Removed broadcast_1939_piece0 on localhost:38805 in memory (size: 8.0 KiB, free: 1919.3 MiB)
18:32:10.175 INFO  BlockManagerInfo - Removed broadcast_1928_piece0 on localhost:38805 in memory (size: 64.0 KiB, free: 1919.3 MiB)
18:32:10.175 INFO  BlockManagerInfo - Removed broadcast_1940_piece0 on localhost:38805 in memory (size: 71.6 KiB, free: 1919.4 MiB)
18:32:10.176 INFO  BlockManagerInfo - Removed broadcast_1948_piece0 on localhost:38805 in memory (size: 22.0 KiB, free: 1919.4 MiB)
18:32:10.176 INFO  BlockManagerInfo - Removed broadcast_1936_piece0 on localhost:38805 in memory (size: 8.5 KiB, free: 1919.4 MiB)
18:32:10.176 INFO  ShuffleBlockFetcherIterator - Getting 1 (251.0 B) non-empty blocks including 1 (251.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.176 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.177 INFO  BlockManagerInfo - Removed broadcast_1927_piece0 on localhost:38805 in memory (size: 71.6 KiB, free: 1919.5 MiB)
18:32:10.179 INFO  Executor - Finished task 0.0 in stage 1210.0 (TID 1041). 2371 bytes result sent to driver
18:32:10.180 INFO  TaskSetManager - Finished task 0.0 in stage 1210.0 (TID 1041) in 7 ms on localhost (executor driver) (1/1)
18:32:10.180 INFO  TaskSchedulerImpl - Removed TaskSet 1210.0, whose tasks have all completed, from pool 
18:32:10.180 INFO  DAGScheduler - ResultStage 1210 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.011 s
18:32:10.180 INFO  DAGScheduler - Job 550 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.180 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1210: Stage finished
18:32:10.180 INFO  DAGScheduler - Job 550 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.062356 s
18:32:10.193 INFO  MemoryStore - Block broadcast_1951 stored as values in memory (estimated size 179.4 KiB, free 1913.7 MiB)
18:32:10.194 INFO  MemoryStore - Block broadcast_1951_piece0 stored as bytes in memory (estimated size 7.9 KiB, free 1913.7 MiB)
18:32:10.195 INFO  BlockManagerInfo - Added broadcast_1951_piece0 in memory on localhost:38805 (size: 7.9 KiB, free: 1919.5 MiB)
18:32:10.195 INFO  SparkContext - Created broadcast 1951 from broadcast at ReadsSparkSink.java:133
18:32:10.199 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:32:10.199 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:32:10.199 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:32:10.212 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:32:10.213 INFO  DAGScheduler - Registering RDD 5384 (mapToPair at SparkUtils.java:161) as input to shuffle 301
18:32:10.213 INFO  DAGScheduler - Got job 551 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:32:10.213 INFO  DAGScheduler - Final stage: ResultStage 1215 (runJob at SparkHadoopWriter.scala:83)
18:32:10.213 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1214)
18:32:10.213 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1214)
18:32:10.214 INFO  DAGScheduler - Submitting ShuffleMapStage 1214 (MapPartitionsRDD[5384] at mapToPair at SparkUtils.java:161), which has no missing parents
18:32:10.215 INFO  MemoryStore - Block broadcast_1952 stored as values in memory (estimated size 51.5 KiB, free 1913.7 MiB)
18:32:10.216 INFO  MemoryStore - Block broadcast_1952_piece0 stored as bytes in memory (estimated size 16.8 KiB, free 1913.6 MiB)
18:32:10.216 INFO  BlockManagerInfo - Added broadcast_1952_piece0 in memory on localhost:38805 (size: 16.8 KiB, free: 1919.5 MiB)
18:32:10.216 INFO  SparkContext - Created broadcast 1952 from broadcast at DAGScheduler.scala:1580
18:32:10.216 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1214 (MapPartitionsRDD[5384] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:32:10.216 INFO  TaskSchedulerImpl - Adding task set 1214.0 with 1 tasks resource profile 0
18:32:10.217 INFO  TaskSetManager - Starting task 0.0 in stage 1214.0 (TID 1042) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:32:10.217 INFO  Executor - Running task 0.0 in stage 1214.0 (TID 1042)
18:32:10.219 INFO  ShuffleBlockFetcherIterator - Getting 1 (16.3 KiB) non-empty blocks including 1 (16.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.219 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.222 INFO  ShuffleBlockFetcherIterator - Getting 1 (2.7 KiB) non-empty blocks including 1 (2.7 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.222 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.224 INFO  Executor - Finished task 0.0 in stage 1214.0 (TID 1042). 1922 bytes result sent to driver
18:32:10.225 INFO  TaskSetManager - Finished task 0.0 in stage 1214.0 (TID 1042) in 7 ms on localhost (executor driver) (1/1)
18:32:10.225 INFO  TaskSchedulerImpl - Removed TaskSet 1214.0, whose tasks have all completed, from pool 
18:32:10.225 INFO  DAGScheduler - ShuffleMapStage 1214 (mapToPair at SparkUtils.java:161) finished in 0.011 s
18:32:10.225 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.225 INFO  DAGScheduler - running: HashSet()
18:32:10.225 INFO  DAGScheduler - waiting: HashSet(ResultStage 1215)
18:32:10.226 INFO  DAGScheduler - failed: HashSet()
18:32:10.226 INFO  DAGScheduler - Submitting ResultStage 1215 (MapPartitionsRDD[5390] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:32:10.237 INFO  MemoryStore - Block broadcast_1953 stored as values in memory (estimated size 196.3 KiB, free 1913.5 MiB)
18:32:10.239 INFO  MemoryStore - Block broadcast_1953_piece0 stored as bytes in memory (estimated size 80.6 KiB, free 1913.4 MiB)
18:32:10.239 INFO  BlockManagerInfo - Added broadcast_1953_piece0 in memory on localhost:38805 (size: 80.6 KiB, free: 1919.4 MiB)
18:32:10.239 INFO  SparkContext - Created broadcast 1953 from broadcast at DAGScheduler.scala:1580
18:32:10.240 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1215 (MapPartitionsRDD[5390] at saveAsTextFile at SamSink.java:65) (first 15 tasks are for partitions Vector(0))
18:32:10.240 INFO  TaskSchedulerImpl - Adding task set 1215.0 with 1 tasks resource profile 0
18:32:10.240 INFO  TaskSetManager - Starting task 0.0 in stage 1215.0 (TID 1043) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.240 INFO  Executor - Running task 0.0 in stage 1215.0 (TID 1043)
18:32:10.245 INFO  ShuffleBlockFetcherIterator - Getting 1 (14.8 KiB) non-empty blocks including 1 (14.8 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.245 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.247 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:32:10.247 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:32:10.248 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:32:10.257 INFO  FileOutputCommitter - Saved output of task 'attempt_20250527183210998691040273905571_5390_m_000000_0' to file:/tmp/MarkDups3244509958907446967/MarkDups.sam.parts/_temporary/0/task_20250527183210998691040273905571_5390_m_000000
18:32:10.257 INFO  SparkHadoopMapRedUtil - attempt_20250527183210998691040273905571_5390_m_000000_0: Committed. Elapsed time: 0 ms.
18:32:10.257 INFO  Executor - Finished task 0.0 in stage 1215.0 (TID 1043). 1858 bytes result sent to driver
18:32:10.258 INFO  TaskSetManager - Finished task 0.0 in stage 1215.0 (TID 1043) in 18 ms on localhost (executor driver) (1/1)
18:32:10.258 INFO  TaskSchedulerImpl - Removed TaskSet 1215.0, whose tasks have all completed, from pool 
18:32:10.258 INFO  DAGScheduler - ResultStage 1215 (runJob at SparkHadoopWriter.scala:83) finished in 0.032 s
18:32:10.258 INFO  DAGScheduler - Job 551 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.258 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1215: Stage finished
18:32:10.258 INFO  DAGScheduler - Job 551 finished: runJob at SparkHadoopWriter.scala:83, took 0.045784 s
18:32:10.258 INFO  SparkHadoopWriter - Start to commit write Job job_20250527183210998691040273905571_5390.
18:32:10.262 INFO  SparkHadoopWriter - Write Job job_20250527183210998691040273905571_5390 committed. Elapsed time: 3 ms.
18:32:10.268 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups3244509958907446967/MarkDups.sam
18:32:10.271 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups3244509958907446967/MarkDups.sam done
18:32:10.271 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:32:10 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1199570944
18:32:10.290 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:10.290 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) v06789f4-SNAPSHOT
18:32:10.290 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:32:10.290 INFO  MarkDuplicatesSpark - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:32:10.290 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:32:10.290 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:32:10 PM GMT
18:32:10.290 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:10.290 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:10.290 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:32:10.290 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
18:32:10.290 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
18:32:10.290 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:32:10.290 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:32:10.290 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:32:10.290 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:32:10.290 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:32:10.290 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:32:10.290 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:32:10.290 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:32:10.290 INFO  MarkDuplicatesSpark - Initializing engine
18:32:10.291 INFO  MarkDuplicatesSpark - Done initializing engine
18:32:10.291 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:32:10.293 INFO  MemoryStore - Block broadcast_1954 stored as values in memory (estimated size 305.5 KiB, free 1913.1 MiB)
18:32:10.300 INFO  MemoryStore - Block broadcast_1954_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1913.0 MiB)
18:32:10.300 INFO  BlockManagerInfo - Added broadcast_1954_piece0 in memory on localhost:38805 (size: 64.0 KiB, free: 1919.4 MiB)
18:32:10.300 INFO  SparkContext - Created broadcast 1954 from newAPIHadoopFile at PathSplitSource.java:96
18:32:10.322 INFO  MemoryStore - Block broadcast_1955 stored as values in memory (estimated size 305.5 KiB, free 1912.7 MiB)
18:32:10.329 INFO  MemoryStore - Block broadcast_1955_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1912.7 MiB)
18:32:10.329 INFO  BlockManagerInfo - Added broadcast_1955_piece0 in memory on localhost:38805 (size: 64.0 KiB, free: 1919.3 MiB)
18:32:10.329 INFO  SparkContext - Created broadcast 1955 from newAPIHadoopFile at PathSplitSource.java:96
18:32:10.361 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:32:10.362 INFO  FileInputFormat - Total input files to process : 1
18:32:10.362 INFO  DAGScheduler - Registering RDD 5404 (mapToPair at SparkUtils.java:161) as input to shuffle 302
18:32:10.363 INFO  DAGScheduler - Got job 552 (collect at SparkUtils.java:205) with 1 output partitions
18:32:10.363 INFO  DAGScheduler - Final stage: ResultStage 1217 (collect at SparkUtils.java:205)
18:32:10.363 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1216)
18:32:10.363 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1216)
18:32:10.363 INFO  DAGScheduler - Submitting ShuffleMapStage 1216 (MapPartitionsRDD[5404] at mapToPair at SparkUtils.java:161), which has no missing parents
18:32:10.380 INFO  MemoryStore - Block broadcast_1956 stored as values in memory (estimated size 456.1 KiB, free 1912.2 MiB)
18:32:10.382 INFO  MemoryStore - Block broadcast_1956_piece0 stored as bytes in memory (estimated size 200.0 KiB, free 1912.0 MiB)
18:32:10.382 INFO  BlockManagerInfo - Added broadcast_1956_piece0 in memory on localhost:38805 (size: 200.0 KiB, free: 1919.1 MiB)
18:32:10.383 INFO  SparkContext - Created broadcast 1956 from broadcast at DAGScheduler.scala:1580
18:32:10.383 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1216 (MapPartitionsRDD[5404] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:32:10.383 INFO  TaskSchedulerImpl - Adding task set 1216.0 with 1 tasks resource profile 0
18:32:10.383 INFO  TaskSetManager - Starting task 0.0 in stage 1216.0 (TID 1044) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9653 bytes) 
18:32:10.383 INFO  Executor - Running task 0.0 in stage 1216.0 (TID 1044)
18:32:10.412 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/optical_dupes.bam:0+678
18:32:10.417 INFO  Executor - Finished task 0.0 in stage 1216.0 (TID 1044). 1148 bytes result sent to driver
18:32:10.417 INFO  TaskSetManager - Finished task 0.0 in stage 1216.0 (TID 1044) in 34 ms on localhost (executor driver) (1/1)
18:32:10.417 INFO  TaskSchedulerImpl - Removed TaskSet 1216.0, whose tasks have all completed, from pool 
18:32:10.417 INFO  DAGScheduler - ShuffleMapStage 1216 (mapToPair at SparkUtils.java:161) finished in 0.054 s
18:32:10.417 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.417 INFO  DAGScheduler - running: HashSet()
18:32:10.417 INFO  DAGScheduler - waiting: HashSet(ResultStage 1217)
18:32:10.417 INFO  DAGScheduler - failed: HashSet()
18:32:10.418 INFO  DAGScheduler - Submitting ResultStage 1217 (MapPartitionsRDD[5407] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:32:10.418 INFO  MemoryStore - Block broadcast_1957 stored as values in memory (estimated size 7.4 KiB, free 1912.0 MiB)
18:32:10.419 INFO  MemoryStore - Block broadcast_1957_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1912.0 MiB)
18:32:10.419 INFO  BlockManagerInfo - Added broadcast_1957_piece0 in memory on localhost:38805 (size: 4.1 KiB, free: 1919.1 MiB)
18:32:10.419 INFO  SparkContext - Created broadcast 1957 from broadcast at DAGScheduler.scala:1580
18:32:10.419 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1217 (MapPartitionsRDD[5407] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:32:10.419 INFO  TaskSchedulerImpl - Adding task set 1217.0 with 1 tasks resource profile 0
18:32:10.420 INFO  TaskSetManager - Starting task 0.0 in stage 1217.0 (TID 1045) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.420 INFO  Executor - Running task 0.0 in stage 1217.0 (TID 1045)
18:32:10.421 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.421 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.422 INFO  Executor - Finished task 0.0 in stage 1217.0 (TID 1045). 2269 bytes result sent to driver
18:32:10.423 INFO  TaskSetManager - Finished task 0.0 in stage 1217.0 (TID 1045) in 3 ms on localhost (executor driver) (1/1)
18:32:10.423 INFO  TaskSchedulerImpl - Removed TaskSet 1217.0, whose tasks have all completed, from pool 
18:32:10.423 INFO  DAGScheduler - ResultStage 1217 (collect at SparkUtils.java:205) finished in 0.005 s
18:32:10.423 INFO  DAGScheduler - Job 552 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.423 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1217: Stage finished
18:32:10.423 INFO  DAGScheduler - Job 552 finished: collect at SparkUtils.java:205, took 0.061315 s
18:32:10.427 INFO  MemoryStore - Block broadcast_1958 stored as values in memory (estimated size 136.0 B, free 1912.0 MiB)
18:32:10.427 INFO  MemoryStore - Block broadcast_1958_piece0 stored as bytes in memory (estimated size 24.0 B, free 1912.0 MiB)
18:32:10.428 INFO  BlockManagerInfo - Added broadcast_1958_piece0 in memory on localhost:38805 (size: 24.0 B, free: 1919.1 MiB)
18:32:10.428 INFO  SparkContext - Created broadcast 1958 from broadcast at MarkDuplicatesSparkUtils.java:126
18:32:10.428 INFO  MemoryStore - Block broadcast_1959 stored as values in memory (estimated size 136.0 B, free 1912.0 MiB)
18:32:10.428 INFO  MemoryStore - Block broadcast_1959_piece0 stored as bytes in memory (estimated size 21.0 B, free 1912.0 MiB)
18:32:10.428 INFO  BlockManagerInfo - Added broadcast_1959_piece0 in memory on localhost:38805 (size: 21.0 B, free: 1919.1 MiB)
18:32:10.429 INFO  SparkContext - Created broadcast 1959 from broadcast at MarkDuplicatesSparkUtils.java:127
18:32:10.440 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:32:10.441 INFO  DAGScheduler - Registering RDD 5416 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 305
18:32:10.441 INFO  DAGScheduler - Registering RDD 5420 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 304
18:32:10.441 INFO  DAGScheduler - Registering RDD 5424 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 303
18:32:10.441 INFO  DAGScheduler - Got job 553 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:32:10.441 INFO  DAGScheduler - Final stage: ResultStage 1222 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:32:10.441 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1221)
18:32:10.441 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1221)
18:32:10.441 INFO  DAGScheduler - Submitting ShuffleMapStage 1219 (MapPartitionsRDD[5416] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:32:10.442 INFO  MemoryStore - Block broadcast_1960 stored as values in memory (estimated size 21.1 KiB, free 1912.0 MiB)
18:32:10.443 INFO  MemoryStore - Block broadcast_1960_piece0 stored as bytes in memory (estimated size 10.9 KiB, free 1912.0 MiB)
18:32:10.443 INFO  BlockManagerInfo - Added broadcast_1960_piece0 in memory on localhost:38805 (size: 10.9 KiB, free: 1919.1 MiB)
18:32:10.443 INFO  SparkContext - Created broadcast 1960 from broadcast at DAGScheduler.scala:1580
18:32:10.443 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1219 (MapPartitionsRDD[5416] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:32:10.443 INFO  TaskSchedulerImpl - Adding task set 1219.0 with 1 tasks resource profile 0
18:32:10.444 INFO  TaskSetManager - Starting task 0.0 in stage 1219.0 (TID 1046) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
18:32:10.444 INFO  Executor - Running task 0.0 in stage 1219.0 (TID 1046)
18:32:10.445 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.446 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.448 INFO  Executor - Finished task 0.0 in stage 1219.0 (TID 1046). 1922 bytes result sent to driver
18:32:10.449 INFO  TaskSetManager - Finished task 0.0 in stage 1219.0 (TID 1046) in 5 ms on localhost (executor driver) (1/1)
18:32:10.449 INFO  TaskSchedulerImpl - Removed TaskSet 1219.0, whose tasks have all completed, from pool 
18:32:10.449 INFO  DAGScheduler - ShuffleMapStage 1219 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.007 s
18:32:10.449 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.449 INFO  DAGScheduler - running: HashSet()
18:32:10.449 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1220, ShuffleMapStage 1221, ResultStage 1222)
18:32:10.449 INFO  DAGScheduler - failed: HashSet()
18:32:10.449 INFO  DAGScheduler - Submitting ShuffleMapStage 1220 (MapPartitionsRDD[5420] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:32:10.450 INFO  MemoryStore - Block broadcast_1961 stored as values in memory (estimated size 25.2 KiB, free 1911.9 MiB)
18:32:10.451 INFO  MemoryStore - Block broadcast_1961_piece0 stored as bytes in memory (estimated size 13.1 KiB, free 1911.9 MiB)
18:32:10.451 INFO  BlockManagerInfo - Added broadcast_1961_piece0 in memory on localhost:38805 (size: 13.1 KiB, free: 1919.1 MiB)
18:32:10.451 INFO  SparkContext - Created broadcast 1961 from broadcast at DAGScheduler.scala:1580
18:32:10.451 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1220 (MapPartitionsRDD[5420] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:32:10.451 INFO  TaskSchedulerImpl - Adding task set 1220.0 with 1 tasks resource profile 0
18:32:10.451 INFO  TaskSetManager - Starting task 0.0 in stage 1220.0 (TID 1047) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
18:32:10.451 INFO  Executor - Running task 0.0 in stage 1220.0 (TID 1047)
18:32:10.453 INFO  ShuffleBlockFetcherIterator - Getting 1 (106.0 B) non-empty blocks including 1 (106.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.453 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.456 INFO  Executor - Finished task 0.0 in stage 1220.0 (TID 1047). 1922 bytes result sent to driver
18:32:10.456 INFO  TaskSetManager - Finished task 0.0 in stage 1220.0 (TID 1047) in 5 ms on localhost (executor driver) (1/1)
18:32:10.456 INFO  TaskSchedulerImpl - Removed TaskSet 1220.0, whose tasks have all completed, from pool 
18:32:10.456 INFO  DAGScheduler - ShuffleMapStage 1220 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.007 s
18:32:10.456 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.456 INFO  DAGScheduler - running: HashSet()
18:32:10.456 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1221, ResultStage 1222)
18:32:10.456 INFO  DAGScheduler - failed: HashSet()
18:32:10.457 INFO  DAGScheduler - Submitting ShuffleMapStage 1221 (MapPartitionsRDD[5424] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:32:10.457 INFO  MemoryStore - Block broadcast_1962 stored as values in memory (estimated size 15.9 KiB, free 1911.9 MiB)
18:32:10.458 INFO  MemoryStore - Block broadcast_1962_piece0 stored as bytes in memory (estimated size 8.3 KiB, free 1911.9 MiB)
18:32:10.458 INFO  BlockManagerInfo - Added broadcast_1962_piece0 in memory on localhost:38805 (size: 8.3 KiB, free: 1919.1 MiB)
18:32:10.458 INFO  SparkContext - Created broadcast 1962 from broadcast at DAGScheduler.scala:1580
18:32:10.458 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1221 (MapPartitionsRDD[5424] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:32:10.458 INFO  TaskSchedulerImpl - Adding task set 1221.0 with 1 tasks resource profile 0
18:32:10.458 INFO  TaskSetManager - Starting task 0.0 in stage 1221.0 (TID 1048) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:32:10.459 INFO  Executor - Running task 0.0 in stage 1221.0 (TID 1048)
18:32:10.460 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.460 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.462 INFO  ShuffleBlockFetcherIterator - Getting 1 (60.0 B) non-empty blocks including 1 (60.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.462 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.463 INFO  Executor - Finished task 0.0 in stage 1221.0 (TID 1048). 1922 bytes result sent to driver
18:32:10.463 INFO  TaskSetManager - Finished task 0.0 in stage 1221.0 (TID 1048) in 5 ms on localhost (executor driver) (1/1)
18:32:10.463 INFO  TaskSchedulerImpl - Removed TaskSet 1221.0, whose tasks have all completed, from pool 
18:32:10.463 INFO  DAGScheduler - ShuffleMapStage 1221 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.006 s
18:32:10.463 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.463 INFO  DAGScheduler - running: HashSet()
18:32:10.464 INFO  DAGScheduler - waiting: HashSet(ResultStage 1222)
18:32:10.464 INFO  DAGScheduler - failed: HashSet()
18:32:10.464 INFO  DAGScheduler - Submitting ResultStage 1222 (MapPartitionsRDD[5426] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:32:10.464 INFO  MemoryStore - Block broadcast_1963 stored as values in memory (estimated size 17.1 KiB, free 1911.9 MiB)
18:32:10.465 INFO  MemoryStore - Block broadcast_1963_piece0 stored as bytes in memory (estimated size 9.0 KiB, free 1911.9 MiB)
18:32:10.465 INFO  BlockManagerInfo - Added broadcast_1963_piece0 in memory on localhost:38805 (size: 9.0 KiB, free: 1919.1 MiB)
18:32:10.465 INFO  SparkContext - Created broadcast 1963 from broadcast at DAGScheduler.scala:1580
18:32:10.465 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1222 (MapPartitionsRDD[5426] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:32:10.465 INFO  TaskSchedulerImpl - Adding task set 1222.0 with 1 tasks resource profile 0
18:32:10.465 INFO  TaskSetManager - Starting task 0.0 in stage 1222.0 (TID 1049) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.466 INFO  Executor - Running task 0.0 in stage 1222.0 (TID 1049)
18:32:10.467 INFO  ShuffleBlockFetcherIterator - Getting 1 (129.0 B) non-empty blocks including 1 (129.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.467 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.468 INFO  Executor - Finished task 0.0 in stage 1222.0 (TID 1049). 1887 bytes result sent to driver
18:32:10.468 INFO  TaskSetManager - Finished task 0.0 in stage 1222.0 (TID 1049) in 3 ms on localhost (executor driver) (1/1)
18:32:10.468 INFO  TaskSchedulerImpl - Removed TaskSet 1222.0, whose tasks have all completed, from pool 
18:32:10.469 INFO  DAGScheduler - ResultStage 1222 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.005 s
18:32:10.469 INFO  DAGScheduler - Job 553 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.469 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1222: Stage finished
18:32:10.469 INFO  DAGScheduler - Job 553 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.028281 s
18:32:10.479 INFO  MemoryStore - Block broadcast_1964 stored as values in memory (estimated size 5.6 KiB, free 1911.9 MiB)
18:32:10.479 INFO  MemoryStore - Block broadcast_1964_piece0 stored as bytes in memory (estimated size 500.0 B, free 1911.9 MiB)
18:32:10.480 INFO  BlockManagerInfo - Added broadcast_1964_piece0 in memory on localhost:38805 (size: 500.0 B, free: 1919.1 MiB)
18:32:10.480 INFO  SparkContext - Created broadcast 1964 from broadcast at ReadsSparkSink.java:133
18:32:10.483 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:32:10.483 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:32:10.483 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:32:10.495 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:32:10.496 INFO  DAGScheduler - Registering RDD 5428 (mapToPair at SparkUtils.java:161) as input to shuffle 306
18:32:10.496 INFO  DAGScheduler - Got job 554 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:32:10.496 INFO  DAGScheduler - Final stage: ResultStage 1227 (runJob at SparkHadoopWriter.scala:83)
18:32:10.496 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1226)
18:32:10.496 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1226)
18:32:10.496 INFO  DAGScheduler - Submitting ShuffleMapStage 1226 (MapPartitionsRDD[5428] at mapToPair at SparkUtils.java:161), which has no missing parents
18:32:10.497 INFO  MemoryStore - Block broadcast_1965 stored as values in memory (estimated size 15.0 KiB, free 1911.9 MiB)
18:32:10.497 INFO  MemoryStore - Block broadcast_1965_piece0 stored as bytes in memory (estimated size 7.8 KiB, free 1911.9 MiB)
18:32:10.497 INFO  BlockManagerInfo - Added broadcast_1965_piece0 in memory on localhost:38805 (size: 7.8 KiB, free: 1919.0 MiB)
18:32:10.497 INFO  SparkContext - Created broadcast 1965 from broadcast at DAGScheduler.scala:1580
18:32:10.498 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1226 (MapPartitionsRDD[5428] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:32:10.498 INFO  TaskSchedulerImpl - Adding task set 1226.0 with 1 tasks resource profile 0
18:32:10.498 INFO  TaskSetManager - Starting task 0.0 in stage 1226.0 (TID 1050) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:32:10.498 INFO  Executor - Running task 0.0 in stage 1226.0 (TID 1050)
18:32:10.500 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.500 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.501 INFO  ShuffleBlockFetcherIterator - Getting 1 (60.0 B) non-empty blocks including 1 (60.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.501 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.502 INFO  Executor - Finished task 0.0 in stage 1226.0 (TID 1050). 1922 bytes result sent to driver
18:32:10.503 INFO  TaskSetManager - Finished task 0.0 in stage 1226.0 (TID 1050) in 5 ms on localhost (executor driver) (1/1)
18:32:10.503 INFO  TaskSchedulerImpl - Removed TaskSet 1226.0, whose tasks have all completed, from pool 
18:32:10.503 INFO  DAGScheduler - ShuffleMapStage 1226 (mapToPair at SparkUtils.java:161) finished in 0.007 s
18:32:10.503 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.503 INFO  DAGScheduler - running: HashSet()
18:32:10.503 INFO  DAGScheduler - waiting: HashSet(ResultStage 1227)
18:32:10.503 INFO  DAGScheduler - failed: HashSet()
18:32:10.503 INFO  DAGScheduler - Submitting ResultStage 1227 (MapPartitionsRDD[5434] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:32:10.510 INFO  MemoryStore - Block broadcast_1966 stored as values in memory (estimated size 159.8 KiB, free 1911.7 MiB)
18:32:10.511 INFO  MemoryStore - Block broadcast_1966_piece0 stored as bytes in memory (estimated size 71.5 KiB, free 1911.6 MiB)
18:32:10.511 INFO  BlockManagerInfo - Added broadcast_1966_piece0 in memory on localhost:38805 (size: 71.5 KiB, free: 1919.0 MiB)
18:32:10.511 INFO  SparkContext - Created broadcast 1966 from broadcast at DAGScheduler.scala:1580
18:32:10.511 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1227 (MapPartitionsRDD[5434] at saveAsTextFile at SamSink.java:65) (first 15 tasks are for partitions Vector(0))
18:32:10.512 INFO  TaskSchedulerImpl - Adding task set 1227.0 with 1 tasks resource profile 0
18:32:10.512 INFO  TaskSetManager - Starting task 0.0 in stage 1227.0 (TID 1051) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.512 INFO  Executor - Running task 0.0 in stage 1227.0 (TID 1051)
18:32:10.516 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.516 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.517 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:32:10.518 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:32:10.518 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:32:10.526 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271832109132163340893630015_5434_m_000000_0' to file:/tmp/MarkDups1607965946741582579/MarkDups.sam.parts/_temporary/0/task_202505271832109132163340893630015_5434_m_000000
18:32:10.527 INFO  SparkHadoopMapRedUtil - attempt_202505271832109132163340893630015_5434_m_000000_0: Committed. Elapsed time: 0 ms.
18:32:10.527 INFO  Executor - Finished task 0.0 in stage 1227.0 (TID 1051). 1858 bytes result sent to driver
18:32:10.527 INFO  TaskSetManager - Finished task 0.0 in stage 1227.0 (TID 1051) in 15 ms on localhost (executor driver) (1/1)
18:32:10.527 INFO  TaskSchedulerImpl - Removed TaskSet 1227.0, whose tasks have all completed, from pool 
18:32:10.528 INFO  DAGScheduler - ResultStage 1227 (runJob at SparkHadoopWriter.scala:83) finished in 0.025 s
18:32:10.528 INFO  DAGScheduler - Job 554 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.528 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1227: Stage finished
18:32:10.528 INFO  DAGScheduler - Job 554 finished: runJob at SparkHadoopWriter.scala:83, took 0.032838 s
18:32:10.528 INFO  SparkHadoopWriter - Start to commit write Job job_202505271832109132163340893630015_5434.
18:32:10.532 INFO  SparkHadoopWriter - Write Job job_202505271832109132163340893630015_5434 committed. Elapsed time: 3 ms.
18:32:10.537 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups1607965946741582579/MarkDups.sam
18:32:10.540 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups1607965946741582579/MarkDups.sam done
18:32:10.540 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:32:10 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
18:32:10.561 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:10.561 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) v06789f4-SNAPSHOT
18:32:10.561 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:32:10.561 INFO  MarkDuplicatesSpark - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:32:10.561 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:32:10.562 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:32:10 PM GMT
18:32:10.562 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:10.562 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:32:10.562 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:32:10.562 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
18:32:10.562 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
18:32:10.562 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:32:10.562 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:32:10.562 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:32:10.562 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:32:10.562 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:32:10.562 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:32:10.562 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:32:10.562 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:32:10.562 INFO  MarkDuplicatesSpark - Initializing engine
18:32:10.562 INFO  MarkDuplicatesSpark - Done initializing engine
18:32:10.562 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:32:10.564 INFO  MemoryStore - Block broadcast_1967 stored as values in memory (estimated size 305.5 KiB, free 1911.3 MiB)
18:32:10.571 INFO  MemoryStore - Block broadcast_1967_piece0 stored as bytes in memory (estimated size 64.1 KiB, free 1911.3 MiB)
18:32:10.572 INFO  BlockManagerInfo - Added broadcast_1967_piece0 in memory on localhost:38805 (size: 64.1 KiB, free: 1918.9 MiB)
18:32:10.572 INFO  SparkContext - Created broadcast 1967 from newAPIHadoopFile at PathSplitSource.java:96
18:32:10.595 INFO  MemoryStore - Block broadcast_1968 stored as values in memory (estimated size 305.5 KiB, free 1911.0 MiB)
18:32:10.602 INFO  MemoryStore - Block broadcast_1968_piece0 stored as bytes in memory (estimated size 64.1 KiB, free 1910.9 MiB)
18:32:10.603 INFO  BlockManagerInfo - Added broadcast_1968_piece0 in memory on localhost:38805 (size: 64.1 KiB, free: 1918.8 MiB)
18:32:10.603 INFO  SparkContext - Created broadcast 1968 from newAPIHadoopFile at PathSplitSource.java:96
18:32:10.640 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:32:10.640 INFO  FileInputFormat - Total input files to process : 1
18:32:10.641 INFO  DAGScheduler - Registering RDD 5448 (mapToPair at SparkUtils.java:161) as input to shuffle 307
18:32:10.641 INFO  DAGScheduler - Got job 555 (collect at SparkUtils.java:205) with 1 output partitions
18:32:10.641 INFO  DAGScheduler - Final stage: ResultStage 1229 (collect at SparkUtils.java:205)
18:32:10.641 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1228)
18:32:10.641 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1228)
18:32:10.641 INFO  DAGScheduler - Submitting ShuffleMapStage 1228 (MapPartitionsRDD[5448] at mapToPair at SparkUtils.java:161), which has no missing parents
18:32:10.660 INFO  MemoryStore - Block broadcast_1969 stored as values in memory (estimated size 480.2 KiB, free 1910.4 MiB)
18:32:10.663 INFO  MemoryStore - Block broadcast_1969_piece0 stored as bytes in memory (estimated size 206.2 KiB, free 1910.2 MiB)
18:32:10.663 INFO  BlockManagerInfo - Added broadcast_1969_piece0 in memory on localhost:38805 (size: 206.2 KiB, free: 1918.6 MiB)
18:32:10.663 INFO  SparkContext - Created broadcast 1969 from broadcast at DAGScheduler.scala:1580
18:32:10.664 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1228 (MapPartitionsRDD[5448] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:32:10.664 INFO  TaskSchedulerImpl - Adding task set 1228.0 with 1 tasks resource profile 0
18:32:10.664 INFO  TaskSetManager - Starting task 0.0 in stage 1228.0 (TID 1052) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9673 bytes) 
18:32:10.665 INFO  Executor - Running task 0.0 in stage 1228.0 (TID 1052)
18:32:10.698 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/inputSingleLibrarySolexa16404.bam:0+5416
18:32:10.704 INFO  Executor - Finished task 0.0 in stage 1228.0 (TID 1052). 1148 bytes result sent to driver
18:32:10.705 INFO  TaskSetManager - Finished task 0.0 in stage 1228.0 (TID 1052) in 40 ms on localhost (executor driver) (1/1)
18:32:10.705 INFO  TaskSchedulerImpl - Removed TaskSet 1228.0, whose tasks have all completed, from pool 
18:32:10.705 INFO  DAGScheduler - ShuffleMapStage 1228 (mapToPair at SparkUtils.java:161) finished in 0.063 s
18:32:10.705 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.705 INFO  DAGScheduler - running: HashSet()
18:32:10.705 INFO  DAGScheduler - waiting: HashSet(ResultStage 1229)
18:32:10.705 INFO  DAGScheduler - failed: HashSet()
18:32:10.705 INFO  DAGScheduler - Submitting ResultStage 1229 (MapPartitionsRDD[5451] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:32:10.706 INFO  MemoryStore - Block broadcast_1970 stored as values in memory (estimated size 7.4 KiB, free 1910.2 MiB)
18:32:10.706 INFO  MemoryStore - Block broadcast_1970_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1910.2 MiB)
18:32:10.707 INFO  BlockManagerInfo - Added broadcast_1970_piece0 in memory on localhost:38805 (size: 4.1 KiB, free: 1918.6 MiB)
18:32:10.707 INFO  SparkContext - Created broadcast 1970 from broadcast at DAGScheduler.scala:1580
18:32:10.707 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1229 (MapPartitionsRDD[5451] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:32:10.707 INFO  TaskSchedulerImpl - Adding task set 1229.0 with 1 tasks resource profile 0
18:32:10.708 INFO  TaskSetManager - Starting task 0.0 in stage 1229.0 (TID 1053) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.708 INFO  Executor - Running task 0.0 in stage 1229.0 (TID 1053)
18:32:10.709 INFO  ShuffleBlockFetcherIterator - Getting 1 (4.3 KiB) non-empty blocks including 1 (4.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.709 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.711 INFO  Executor - Finished task 0.0 in stage 1229.0 (TID 1053). 2039 bytes result sent to driver
18:32:10.711 INFO  TaskSetManager - Finished task 0.0 in stage 1229.0 (TID 1053) in 4 ms on localhost (executor driver) (1/1)
18:32:10.711 INFO  TaskSchedulerImpl - Removed TaskSet 1229.0, whose tasks have all completed, from pool 
18:32:10.711 INFO  DAGScheduler - ResultStage 1229 (collect at SparkUtils.java:205) finished in 0.006 s
18:32:10.711 INFO  DAGScheduler - Job 555 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.711 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1229: Stage finished
18:32:10.712 INFO  DAGScheduler - Job 555 finished: collect at SparkUtils.java:205, took 0.071795 s
18:32:10.716 INFO  MemoryStore - Block broadcast_1971 stored as values in memory (estimated size 392.0 B, free 1910.2 MiB)
18:32:10.722 INFO  MemoryStore - Block broadcast_1971_piece0 stored as bytes in memory (estimated size 33.0 B, free 1910.2 MiB)
18:32:10.722 INFO  BlockManagerInfo - Added broadcast_1971_piece0 in memory on localhost:38805 (size: 33.0 B, free: 1918.6 MiB)
18:32:10.722 INFO  SparkContext - Created broadcast 1971 from broadcast at MarkDuplicatesSparkUtils.java:126
18:32:10.722 INFO  BlockManagerInfo - Removed broadcast_1942_piece0 on localhost:38805 in memory (size: 64.0 KiB, free: 1918.7 MiB)
18:32:10.723 INFO  MemoryStore - Block broadcast_1972 stored as values in memory (estimated size 144.0 B, free 1910.6 MiB)
18:32:10.723 INFO  BlockManagerInfo - Removed broadcast_1961_piece0 on localhost:38805 in memory (size: 13.1 KiB, free: 1918.7 MiB)
18:32:10.723 INFO  MemoryStore - Block broadcast_1972_piece0 stored as bytes in memory (estimated size 28.0 B, free 1910.6 MiB)
18:32:10.723 INFO  BlockManagerInfo - Added broadcast_1972_piece0 in memory on localhost:38805 (size: 28.0 B, free: 1918.7 MiB)
18:32:10.724 INFO  BlockManagerInfo - Removed broadcast_1962_piece0 on localhost:38805 in memory (size: 8.3 KiB, free: 1918.7 MiB)
18:32:10.724 INFO  SparkContext - Created broadcast 1972 from broadcast at MarkDuplicatesSparkUtils.java:127
18:32:10.724 INFO  BlockManagerInfo - Removed broadcast_1969_piece0 on localhost:38805 in memory (size: 206.2 KiB, free: 1918.9 MiB)
18:32:10.725 INFO  BlockManagerInfo - Removed broadcast_1958_piece0 on localhost:38805 in memory (size: 24.0 B, free: 1918.9 MiB)
18:32:10.725 INFO  BlockManagerInfo - Removed broadcast_1957_piece0 on localhost:38805 in memory (size: 4.1 KiB, free: 1918.9 MiB)
18:32:10.725 INFO  BlockManagerInfo - Removed broadcast_1949_piece0 on localhost:38805 in memory (size: 17.3 KiB, free: 1918.9 MiB)
18:32:10.726 INFO  BlockManagerInfo - Removed broadcast_1965_piece0 on localhost:38805 in memory (size: 7.8 KiB, free: 1919.0 MiB)
18:32:10.726 INFO  BlockManagerInfo - Removed broadcast_1956_piece0 on localhost:38805 in memory (size: 200.0 KiB, free: 1919.2 MiB)
18:32:10.727 INFO  BlockManagerInfo - Removed broadcast_1953_piece0 on localhost:38805 in memory (size: 80.6 KiB, free: 1919.2 MiB)
18:32:10.727 INFO  BlockManagerInfo - Removed broadcast_1952_piece0 on localhost:38805 in memory (size: 16.8 KiB, free: 1919.2 MiB)
18:32:10.727 INFO  BlockManagerInfo - Removed broadcast_1959_piece0 on localhost:38805 in memory (size: 21.0 B, free: 1919.2 MiB)
18:32:10.729 INFO  BlockManagerInfo - Removed broadcast_1946_piece0 on localhost:38805 in memory (size: 209.0 B, free: 1919.2 MiB)
18:32:10.729 INFO  BlockManagerInfo - Removed broadcast_1950_piece0 on localhost:38805 in memory (size: 18.0 KiB, free: 1919.3 MiB)
18:32:10.730 INFO  BlockManagerInfo - Removed broadcast_1960_piece0 on localhost:38805 in memory (size: 10.9 KiB, free: 1919.3 MiB)
18:32:10.730 INFO  BlockManagerInfo - Removed broadcast_1963_piece0 on localhost:38805 in memory (size: 9.0 KiB, free: 1919.3 MiB)
18:32:10.731 INFO  BlockManagerInfo - Removed broadcast_1970_piece0 on localhost:38805 in memory (size: 4.1 KiB, free: 1919.3 MiB)
18:32:10.731 INFO  BlockManagerInfo - Removed broadcast_1951_piece0 on localhost:38805 in memory (size: 7.9 KiB, free: 1919.3 MiB)
18:32:10.731 INFO  BlockManagerInfo - Removed broadcast_1964_piece0 on localhost:38805 in memory (size: 500.0 B, free: 1919.3 MiB)
18:32:10.732 INFO  BlockManagerInfo - Removed broadcast_1954_piece0 on localhost:38805 in memory (size: 64.0 KiB, free: 1919.4 MiB)
18:32:10.732 INFO  BlockManagerInfo - Removed broadcast_1955_piece0 on localhost:38805 in memory (size: 64.0 KiB, free: 1919.4 MiB)
18:32:10.732 INFO  BlockManagerInfo - Removed broadcast_1967_piece0 on localhost:38805 in memory (size: 64.1 KiB, free: 1919.5 MiB)
18:32:10.733 INFO  BlockManagerInfo - Removed broadcast_1966_piece0 on localhost:38805 in memory (size: 71.5 KiB, free: 1919.6 MiB)
18:32:10.734 INFO  BlockManagerInfo - Removed broadcast_1945_piece0 on localhost:38805 in memory (size: 540.0 B, free: 1919.6 MiB)
18:32:10.740 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:32:10.740 INFO  DAGScheduler - Registering RDD 5460 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 310
18:32:10.741 INFO  DAGScheduler - Registering RDD 5464 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 309
18:32:10.741 INFO  DAGScheduler - Registering RDD 5468 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 308
18:32:10.741 INFO  DAGScheduler - Got job 556 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:32:10.741 INFO  DAGScheduler - Final stage: ResultStage 1234 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:32:10.741 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1233)
18:32:10.741 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1233)
18:32:10.741 INFO  DAGScheduler - Submitting ShuffleMapStage 1231 (MapPartitionsRDD[5460] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:32:10.742 INFO  MemoryStore - Block broadcast_1973 stored as values in memory (estimated size 45.2 KiB, free 1914.0 MiB)
18:32:10.743 INFO  MemoryStore - Block broadcast_1973_piece0 stored as bytes in memory (estimated size 17.1 KiB, free 1914.0 MiB)
18:32:10.743 INFO  BlockManagerInfo - Added broadcast_1973_piece0 in memory on localhost:38805 (size: 17.1 KiB, free: 1919.5 MiB)
18:32:10.743 INFO  SparkContext - Created broadcast 1973 from broadcast at DAGScheduler.scala:1580
18:32:10.744 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1231 (MapPartitionsRDD[5460] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:32:10.744 INFO  TaskSchedulerImpl - Adding task set 1231.0 with 1 tasks resource profile 0
18:32:10.744 INFO  TaskSetManager - Starting task 0.0 in stage 1231.0 (TID 1054) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
18:32:10.745 INFO  Executor - Running task 0.0 in stage 1231.0 (TID 1054)
18:32:10.746 INFO  ShuffleBlockFetcherIterator - Getting 1 (4.3 KiB) non-empty blocks including 1 (4.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.746 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.750 INFO  Executor - Finished task 0.0 in stage 1231.0 (TID 1054). 1922 bytes result sent to driver
18:32:10.750 INFO  TaskSetManager - Finished task 0.0 in stage 1231.0 (TID 1054) in 6 ms on localhost (executor driver) (1/1)
18:32:10.750 INFO  TaskSchedulerImpl - Removed TaskSet 1231.0, whose tasks have all completed, from pool 
18:32:10.750 INFO  DAGScheduler - ShuffleMapStage 1231 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.009 s
18:32:10.750 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.751 INFO  DAGScheduler - running: HashSet()
18:32:10.751 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1232, ShuffleMapStage 1233, ResultStage 1234)
18:32:10.751 INFO  DAGScheduler - failed: HashSet()
18:32:10.751 INFO  DAGScheduler - Submitting ShuffleMapStage 1232 (MapPartitionsRDD[5464] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:32:10.752 INFO  MemoryStore - Block broadcast_1974 stored as values in memory (estimated size 49.3 KiB, free 1913.9 MiB)
18:32:10.753 INFO  MemoryStore - Block broadcast_1974_piece0 stored as bytes in memory (estimated size 19.3 KiB, free 1913.9 MiB)
18:32:10.753 INFO  BlockManagerInfo - Added broadcast_1974_piece0 in memory on localhost:38805 (size: 19.3 KiB, free: 1919.5 MiB)
18:32:10.753 INFO  SparkContext - Created broadcast 1974 from broadcast at DAGScheduler.scala:1580
18:32:10.753 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1232 (MapPartitionsRDD[5464] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:32:10.754 INFO  TaskSchedulerImpl - Adding task set 1232.0 with 1 tasks resource profile 0
18:32:10.754 INFO  TaskSetManager - Starting task 0.0 in stage 1232.0 (TID 1055) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
18:32:10.754 INFO  Executor - Running task 0.0 in stage 1232.0 (TID 1055)
18:32:10.757 INFO  ShuffleBlockFetcherIterator - Getting 1 (593.0 B) non-empty blocks including 1 (593.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.757 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.761 INFO  Executor - Finished task 0.0 in stage 1232.0 (TID 1055). 1922 bytes result sent to driver
18:32:10.761 INFO  TaskSetManager - Finished task 0.0 in stage 1232.0 (TID 1055) in 7 ms on localhost (executor driver) (1/1)
18:32:10.761 INFO  TaskSchedulerImpl - Removed TaskSet 1232.0, whose tasks have all completed, from pool 
18:32:10.761 INFO  DAGScheduler - ShuffleMapStage 1232 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.010 s
18:32:10.761 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.761 INFO  DAGScheduler - running: HashSet()
18:32:10.762 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1233, ResultStage 1234)
18:32:10.762 INFO  DAGScheduler - failed: HashSet()
18:32:10.762 INFO  DAGScheduler - Submitting ShuffleMapStage 1233 (MapPartitionsRDD[5468] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:32:10.763 INFO  MemoryStore - Block broadcast_1975 stored as values in memory (estimated size 40.0 KiB, free 1913.9 MiB)
18:32:10.764 INFO  MemoryStore - Block broadcast_1975_piece0 stored as bytes in memory (estimated size 14.5 KiB, free 1913.9 MiB)
18:32:10.764 INFO  BlockManagerInfo - Added broadcast_1975_piece0 in memory on localhost:38805 (size: 14.5 KiB, free: 1919.5 MiB)
18:32:10.764 INFO  SparkContext - Created broadcast 1975 from broadcast at DAGScheduler.scala:1580
18:32:10.764 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1233 (MapPartitionsRDD[5468] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:32:10.764 INFO  TaskSchedulerImpl - Adding task set 1233.0 with 1 tasks resource profile 0
18:32:10.765 INFO  TaskSetManager - Starting task 0.0 in stage 1233.0 (TID 1056) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:32:10.765 INFO  Executor - Running task 0.0 in stage 1233.0 (TID 1056)
18:32:10.767 INFO  ShuffleBlockFetcherIterator - Getting 1 (4.3 KiB) non-empty blocks including 1 (4.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.767 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.770 INFO  ShuffleBlockFetcherIterator - Getting 1 (652.0 B) non-empty blocks including 1 (652.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.770 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.771 INFO  Executor - Finished task 0.0 in stage 1233.0 (TID 1056). 1922 bytes result sent to driver
18:32:10.772 INFO  TaskSetManager - Finished task 0.0 in stage 1233.0 (TID 1056) in 7 ms on localhost (executor driver) (1/1)
18:32:10.772 INFO  TaskSchedulerImpl - Removed TaskSet 1233.0, whose tasks have all completed, from pool 
18:32:10.772 INFO  DAGScheduler - ShuffleMapStage 1233 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.010 s
18:32:10.772 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.772 INFO  DAGScheduler - running: HashSet()
18:32:10.772 INFO  DAGScheduler - waiting: HashSet(ResultStage 1234)
18:32:10.772 INFO  DAGScheduler - failed: HashSet()
18:32:10.772 INFO  DAGScheduler - Submitting ResultStage 1234 (MapPartitionsRDD[5470] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:32:10.774 INFO  MemoryStore - Block broadcast_1976 stored as values in memory (estimated size 41.2 KiB, free 1913.8 MiB)
18:32:10.775 INFO  MemoryStore - Block broadcast_1976_piece0 stored as bytes in memory (estimated size 15.3 KiB, free 1913.8 MiB)
18:32:10.775 INFO  BlockManagerInfo - Added broadcast_1976_piece0 in memory on localhost:38805 (size: 15.3 KiB, free: 1919.5 MiB)
18:32:10.775 INFO  SparkContext - Created broadcast 1976 from broadcast at DAGScheduler.scala:1580
18:32:10.775 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1234 (MapPartitionsRDD[5470] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:32:10.775 INFO  TaskSchedulerImpl - Adding task set 1234.0 with 1 tasks resource profile 0
18:32:10.776 INFO  TaskSetManager - Starting task 0.0 in stage 1234.0 (TID 1057) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.776 INFO  Executor - Running task 0.0 in stage 1234.0 (TID 1057)
18:32:10.778 INFO  ShuffleBlockFetcherIterator - Getting 1 (142.0 B) non-empty blocks including 1 (142.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.778 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.780 INFO  Executor - Finished task 0.0 in stage 1234.0 (TID 1057). 1944 bytes result sent to driver
18:32:10.780 INFO  TaskSetManager - Finished task 0.0 in stage 1234.0 (TID 1057) in 4 ms on localhost (executor driver) (1/1)
18:32:10.780 INFO  TaskSchedulerImpl - Removed TaskSet 1234.0, whose tasks have all completed, from pool 
18:32:10.780 INFO  DAGScheduler - ResultStage 1234 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.007 s
18:32:10.780 INFO  DAGScheduler - Job 556 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.780 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1234: Stage finished
18:32:10.780 INFO  DAGScheduler - Job 556 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.040331 s
18:32:10.793 INFO  MemoryStore - Block broadcast_1977 stored as values in memory (estimated size 93.5 KiB, free 1913.7 MiB)
18:32:10.794 INFO  MemoryStore - Block broadcast_1977_piece0 stored as bytes in memory (estimated size 5.6 KiB, free 1913.7 MiB)
18:32:10.794 INFO  BlockManagerInfo - Added broadcast_1977_piece0 in memory on localhost:38805 (size: 5.6 KiB, free: 1919.5 MiB)
18:32:10.794 INFO  SparkContext - Created broadcast 1977 from broadcast at ReadsSparkSink.java:133
18:32:10.798 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:32:10.798 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:32:10.798 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:32:10.811 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:32:10.812 INFO  DAGScheduler - Registering RDD 5472 (mapToPair at SparkUtils.java:161) as input to shuffle 311
18:32:10.812 INFO  DAGScheduler - Got job 557 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:32:10.812 INFO  DAGScheduler - Final stage: ResultStage 1239 (runJob at SparkHadoopWriter.scala:83)
18:32:10.812 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1238)
18:32:10.812 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1238)
18:32:10.812 INFO  DAGScheduler - Submitting ShuffleMapStage 1238 (MapPartitionsRDD[5472] at mapToPair at SparkUtils.java:161), which has no missing parents
18:32:10.813 INFO  MemoryStore - Block broadcast_1978 stored as values in memory (estimated size 39.1 KiB, free 1913.7 MiB)
18:32:10.814 INFO  MemoryStore - Block broadcast_1978_piece0 stored as bytes in memory (estimated size 14.1 KiB, free 1913.7 MiB)
18:32:10.814 INFO  BlockManagerInfo - Added broadcast_1978_piece0 in memory on localhost:38805 (size: 14.1 KiB, free: 1919.5 MiB)
18:32:10.814 INFO  SparkContext - Created broadcast 1978 from broadcast at DAGScheduler.scala:1580
18:32:10.815 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1238 (MapPartitionsRDD[5472] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:32:10.815 INFO  TaskSchedulerImpl - Adding task set 1238.0 with 1 tasks resource profile 0
18:32:10.815 INFO  TaskSetManager - Starting task 0.0 in stage 1238.0 (TID 1058) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
18:32:10.815 INFO  Executor - Running task 0.0 in stage 1238.0 (TID 1058)
18:32:10.817 INFO  ShuffleBlockFetcherIterator - Getting 1 (4.3 KiB) non-empty blocks including 1 (4.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.817 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.819 INFO  ShuffleBlockFetcherIterator - Getting 1 (652.0 B) non-empty blocks including 1 (652.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.819 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.821 INFO  Executor - Finished task 0.0 in stage 1238.0 (TID 1058). 1922 bytes result sent to driver
18:32:10.821 INFO  TaskSetManager - Finished task 0.0 in stage 1238.0 (TID 1058) in 6 ms on localhost (executor driver) (1/1)
18:32:10.821 INFO  TaskSchedulerImpl - Removed TaskSet 1238.0, whose tasks have all completed, from pool 
18:32:10.821 INFO  DAGScheduler - ShuffleMapStage 1238 (mapToPair at SparkUtils.java:161) finished in 0.009 s
18:32:10.821 INFO  DAGScheduler - looking for newly runnable stages
18:32:10.821 INFO  DAGScheduler - running: HashSet()
18:32:10.822 INFO  DAGScheduler - waiting: HashSet(ResultStage 1239)
18:32:10.822 INFO  DAGScheduler - failed: HashSet()
18:32:10.822 INFO  DAGScheduler - Submitting ResultStage 1239 (MapPartitionsRDD[5478] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:32:10.829 INFO  MemoryStore - Block broadcast_1979 stored as values in memory (estimated size 183.9 KiB, free 1913.5 MiB)
18:32:10.830 INFO  MemoryStore - Block broadcast_1979_piece0 stored as bytes in memory (estimated size 77.8 KiB, free 1913.4 MiB)
18:32:10.830 INFO  BlockManagerInfo - Added broadcast_1979_piece0 in memory on localhost:38805 (size: 77.8 KiB, free: 1919.4 MiB)
18:32:10.830 INFO  SparkContext - Created broadcast 1979 from broadcast at DAGScheduler.scala:1580
18:32:10.831 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1239 (MapPartitionsRDD[5478] at saveAsTextFile at SamSink.java:65) (first 15 tasks are for partitions Vector(0))
18:32:10.831 INFO  TaskSchedulerImpl - Adding task set 1239.0 with 1 tasks resource profile 0
18:32:10.831 INFO  TaskSetManager - Starting task 0.0 in stage 1239.0 (TID 1059) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
18:32:10.832 INFO  Executor - Running task 0.0 in stage 1239.0 (TID 1059)
18:32:10.836 INFO  ShuffleBlockFetcherIterator - Getting 1 (3.9 KiB) non-empty blocks including 1 (3.9 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:32:10.836 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:32:10.838 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:32:10.838 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:32:10.838 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:32:10.846 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271832106320927086811012_5478_m_000000_0' to file:/tmp/MarkDups7519760215963598138/MarkDups.sam.parts/_temporary/0/task_202505271832106320927086811012_5478_m_000000
18:32:10.846 INFO  SparkHadoopMapRedUtil - attempt_202505271832106320927086811012_5478_m_000000_0: Committed. Elapsed time: 0 ms.
18:32:10.846 INFO  Executor - Finished task 0.0 in stage 1239.0 (TID 1059). 1858 bytes result sent to driver
18:32:10.847 INFO  TaskSetManager - Finished task 0.0 in stage 1239.0 (TID 1059) in 16 ms on localhost (executor driver) (1/1)
18:32:10.847 INFO  TaskSchedulerImpl - Removed TaskSet 1239.0, whose tasks have all completed, from pool 
18:32:10.847 INFO  DAGScheduler - ResultStage 1239 (runJob at SparkHadoopWriter.scala:83) finished in 0.025 s
18:32:10.847 INFO  DAGScheduler - Job 557 is finished. Cancelling potential speculative or zombie tasks for this job
18:32:10.847 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1239: Stage finished
18:32:10.847 INFO  DAGScheduler - Job 557 finished: runJob at SparkHadoopWriter.scala:83, took 0.036000 s
18:32:10.847 INFO  SparkHadoopWriter - Start to commit write Job job_202505271832106320927086811012_5478.
18:32:10.851 INFO  SparkHadoopWriter - Write Job job_202505271832106320927086811012_5478 committed. Elapsed time: 3 ms.
18:32:10.856 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups7519760215963598138/MarkDups.sam
18:32:10.859 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups7519760215963598138/MarkDups.sam done
18:32:10.859 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:32:10 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:11 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:11 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:11 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:12 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:12 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:13 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:13 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:13 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:14 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:14 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:15 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:15 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:15 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:16 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:16 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:16 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:17 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:17 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
18:32:17.839 ERROR Executor - Exception in task 0.0 in stage 1459.0 (TID 1206)
org.broadinstitute.hellbender.exceptions.UserException$ReadMissingReadGroup: SAM/BAM/CRAM file (unknown) is malformed: Read RUNID:7:1203:2886:82292 is missing the read group (RG) tag, which is required by the GATK.  Please use http://gatkforums.broadinstitute.org/discussion/59/companion-utilities-replacereadgroups to fix this problem
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.getLibraryForRead(MarkDuplicatesSparkUtils.java:64) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.EmptyFragment.<init>(EmptyFragment.java:36) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.MarkDuplicatesSparkRecord.newEmptyFragment(MarkDuplicatesSparkRecord.java:44) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.lambda$transformToDuplicateNames$0(MarkDuplicatesSparkUtils.java:141) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at java.base/java.util.stream.ReferencePipeline$15$1.accept(ReferencePipeline.java:540) ~[?:?]
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1625) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[?:?]
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:921) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:682) ~[?:?]
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.lambda$transformToDuplicateNames$5ac2632f$1(MarkDuplicatesSparkUtils.java:150) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.api.java.JavaRDDLike.$anonfun$flatMapToPair$1(JavaRDDLike.scala:143) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at scala.collection.Iterator$$anon$10.nextCur(Iterator.scala:594) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:608) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.shuffle.sort.BypassMergeSortShuffleWriter.write(BypassMergeSortShuffleWriter.java:140) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.shuffle.ShuffleWriteProcessor.write(ShuffleWriteProcessor.scala:59) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:104) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:54) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.TaskContext.runTaskWithListeners(TaskContext.scala:161) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.scheduler.Task.run(Task.scala:141) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.executor.Executor$TaskRunner.$anonfun$run$4(Executor.scala:620) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally(SparkErrorUtils.scala:64) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally$(SparkErrorUtils.scala:61) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.util.Utils$.tryWithSafeFinally(Utils.scala:94) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:623) [gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
18:32:17.860 ERROR TaskSetManager - Task 0 in stage 1459.0 failed 1 times; aborting job
[May 27, 2025 at 6:32:17 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
18:32:18.152 ERROR Executor - Exception in task 0.0 in stage 1466.0 (TID 1209)
org.broadinstitute.hellbender.exceptions.UserException$HeaderMissingReadGroup: SAM/BAM/CRAM file (unknown) is malformed: Read RUNID:7:1203:2886:82292 contains an (RG) tag with the group NotADuplicateGroup which is not found in the file header.
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.getLibraryForRead(MarkDuplicatesSparkUtils.java:66) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.EmptyFragment.<init>(EmptyFragment.java:36) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.MarkDuplicatesSparkRecord.newEmptyFragment(MarkDuplicatesSparkRecord.java:44) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.lambda$transformToDuplicateNames$0(MarkDuplicatesSparkUtils.java:141) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at java.base/java.util.stream.ReferencePipeline$15$1.accept(ReferencePipeline.java:540) ~[?:?]
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1625) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[?:?]
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:921) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:682) ~[?:?]
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.lambda$transformToDuplicateNames$5ac2632f$1(MarkDuplicatesSparkUtils.java:150) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.api.java.JavaRDDLike.$anonfun$flatMapToPair$1(JavaRDDLike.scala:143) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at scala.collection.Iterator$$anon$10.nextCur(Iterator.scala:594) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:608) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.shuffle.sort.BypassMergeSortShuffleWriter.write(BypassMergeSortShuffleWriter.java:140) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.shuffle.ShuffleWriteProcessor.write(ShuffleWriteProcessor.scala:59) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:104) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:54) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.TaskContext.runTaskWithListeners(TaskContext.scala:161) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.scheduler.Task.run(Task.scala:141) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.executor.Executor$TaskRunner.$anonfun$run$4(Executor.scala:620) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally(SparkErrorUtils.scala:64) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally$(SparkErrorUtils.scala:61) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.util.Utils$.tryWithSafeFinally(Utils.scala:94) ~[gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:623) [gatk-package-06789f4-SNAPSHOT-local.jar:06789f4-SNAPSHOT]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
18:32:18.155 ERROR TaskSetManager - Task 0 in stage 1466.0 failed 1 times; aborting job
[May 27, 2025 at 6:32:18 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:18 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:18 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:19 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:19 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:20 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:20 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:20 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:21 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:21 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:21 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:22 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:22 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:22 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:23 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:23 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:24 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:24 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:24 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:25 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:25 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:25 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:26 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:26 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:26 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:27 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:27 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:27 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:28 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:28 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:29 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:29 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:29 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:30 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:30 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:30 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:31 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:31 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:31 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:32 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:32 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:33 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:33 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:33 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:34 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:34 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:35 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:35 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:35 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:36 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:36 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:36 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:38 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:38 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:39 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:39 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:39 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:40 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:40 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:40 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:41 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:41 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:42 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:42 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:42 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:43 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:43 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:43 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:44 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:44 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:45 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:45 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:45 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:46 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:46 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:46 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:47 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:47 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944
[May 27, 2025 at 6:32:48 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1199570944