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

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

tests
0

failures
0

ignored
1m0.10s

duration
100%

successful

Tests

Test Duration Result
assertThatExpectedOutputUpdateToggleIsDisabled 0s passed
testAssertAssumeUnsortedFilesAreQueryGroupedFiles 0.566s passed
testAssertCorrectSortOrderMultipleBams 0.148s passed
testAssertCorrectSortOrderMultipleBamsOverriding 0.520s passed
testBulkFragmentsNoDuplicates 0.932s passed
testBulkFragmentsWithDuplicates 2.054s passed
testDifferentChromosomesInOppositeOrder 0.303s 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.278s 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.245s 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.264s passed
testFlowModeFlag 1.588s passed
testHashCollisionHandling 1.059s 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.303s 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.272s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[0](true, true, true) 0.299s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[1](true, false, true) 0.307s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[2](false, true, true) 0.309s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[3](true, true, false) 0.312s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[4](true, false, false) 0.297s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[5](false, true, false) 0.309s passed
testMappedFragmentAndMappedPairFirstOfPairNonPrimary 0.303s passed
testMappedFragmentAndMatePairFirstUnmapped 0.305s passed
testMappedFragmentAndMatePairSecondUnmapped 0.298s passed
testMappedPairAndMappedFragmentAndMatePairFirstUnmapped 0.301s passed
testMappedPairAndMappedFragmentAndMatePairSecondUnmapped 0.320s passed
testMappedPairAndMatePairFirstOppositeStrandSecondUnmapped 0.328s passed
testMappedPairAndMatePairFirstUnmapped 0.299s passed
testMappedPairAndMatePairSecondUnmapped 0.303s passed
testMappedPairWithFirstEndSamePositionAndOther 0.309s passed
testMappedPairWithSamePosition 0.316s passed
testMappedPairWithSamePositionSameCigar 0.301s passed
testMarkDuplicatesSparkDeletingDuplicateReads[0]([Ljava.io.File;@11f780ea, 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.372s passed
testMarkDuplicatesSparkDeletingDuplicateReads[1]([Ljava.io.File;@a388bf1, 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.395s passed
testMarkDuplicatesSparkDeletingDuplicateReads[2]([Ljava.io.File;@7e875c3e, 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.409s passed
testMarkDuplicatesSparkDeletingDuplicateReads[3]([Ljava.io.File;@5e58c24b, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.331s passed
testMarkDuplicatesSparkDeletingDuplicateReads[4]([Ljava.io.File;@3a711fc0, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.325s passed
testMarkDuplicatesSparkDeletingDuplicateReads[5]([Ljava.io.File;@145efb2e, 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.196s passed
testMarkDuplicatesSparkDeletingDuplicateReads[6]([Ljava.io.File;@37512792, 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.198s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[0]([Ljava.io.File;@5b5b978e, 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.360s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[1]([Ljava.io.File;@62cc5e25, 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.400s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[2]([Ljava.io.File;@1969e47e, 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.424s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[3]([Ljava.io.File;@5e2ee238, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.363s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[4]([Ljava.io.File;@6faf862b, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.332s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[5]([Ljava.io.File;@646885c5, 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.197s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[6]([Ljava.io.File;@7da5a7ab, 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.150s passed
testMarkDuplicatesSparkIntegrationTestLocal[0]([Ljava.io.File;@254e3e83, 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.346s passed
testMarkDuplicatesSparkIntegrationTestLocal[1]([Ljava.io.File;@36d39092, 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.358s passed
testMarkDuplicatesSparkIntegrationTestLocal[2]([Ljava.io.File;@34ea8728, 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.377s passed
testMarkDuplicatesSparkIntegrationTestLocal[3]([Ljava.io.File;@72cc8784, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.316s passed
testMarkDuplicatesSparkIntegrationTestLocal[4]([Ljava.io.File;@5473d4b6, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.333s passed
testMarkDuplicatesSparkIntegrationTestLocal[5]([Ljava.io.File;@5242e92b, 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.167s passed
testMarkDuplicatesSparkIntegrationTestLocal[6]([Ljava.io.File;@19f8b18c, 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.176s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[0]([Ljava.io.File;@2d216b8a, 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.359s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[1]([Ljava.io.File;@599575fa, 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.356s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[2]([Ljava.io.File;@4ef8158b, 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.340s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[3]([Ljava.io.File;@4e0c2b85, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.317s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[4]([Ljava.io.File;@600dc898, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.329s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[5]([Ljava.io.File;@5753cac3, 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.131s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[6]([Ljava.io.File;@19c6b02d, 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.164s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[0]([Ljava.io.File;@ec7d49a, 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.345s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[1]([Ljava.io.File;@6bd02eb, 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.349s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[2]([Ljava.io.File;@480ce1b8, 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.358s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[3]([Ljava.io.File;@5e16f2d2, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.332s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[4]([Ljava.io.File;@518aa970, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.311s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[5]([Ljava.io.File;@4791739, 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.141s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[6]([Ljava.io.File;@55e736ac, 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.140s passed
testMatePairFirstUnmapped 0.295s passed
testMatePairSecondUnmapped 0.303s passed
testNoReadGroupInRead 0.249s passed
testNonExistantReadGroupInRead 0.237s passed
testNullOpticalDuplicates 0.313s passed
testOpticalDuplicateClusterOneEndSamePositionOneCluster 0.312s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicatesWithinPixelDistance 0.292s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[0](RUNID:7:1203:2886:82292, RUNID:7:1205:3886:16834) 0.323s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[10](RUNID:7:1203:6886:16756, RUNID:7:1203:4886:26756) 0.307s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[11](RUNID:7:1203:2886:34756, RUNID:7:1203:2886:36756) 0.297s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[12](RUNID:7:1203:2886:35756, RUNID:7:1203:2886:36756) 0.297s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[13](RUNID:7:1203:2886:37756, RUNID:7:1203:2886:36756) 0.308s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[14](RUNID:7:1203:2886:38756, RUNID:7:1203:2886:36756) 0.305s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[15](HK3T5CCXX160204:3:1112:11586:37067, HK3T5CCXX160204:3:1112:11586:32144) 0.302s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[1](RUNID:7:1203:2886:16756, RUNID:7:1205:3886:16756) 0.305s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[2](RUNID:7:1204:2886:16756, RUNID:7:1205:3886:16756) 0.307s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[3](RUNID:7:1205:2886:16756, RUNID:7:1205:3886:16756) 0.318s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[4](RUNID:7:1206:2886:16756, RUNID:7:1205:3886:16756) 0.297s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[5](RUNID:7:1207:2886:16756, RUNID:7:1205:3886:16756) 0.301s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[6](RUNID:7:1203:2886:16756, RUNID:7:1203:4886:26756) 0.309s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[7](RUNID:7:1203:3886:16756, RUNID:7:1203:4886:26756) 0.304s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[8](RUNID:7:1203:4886:16756, RUNID:7:1203:4886:26756) 0.301s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[9](RUNID:7:1203:5886:16756, RUNID:7:1203:4886:26756) 0.303s passed
testOpticalDuplicateClusterSamePositionOneOpticalDuplicatesWithinPixelDistance 0.302s passed
testOpticalDuplicateClustersAddingSecondEndFirstSameCoordinate 0.308s passed
testOpticalDuplicateFinding 0.304s passed
testOpticalDuplicateFindingPxelDistance 0.295s passed
testOpticalDuplicatesAndPCRDuplicatesOrientationDifference 0.302s passed
testOpticalDuplicatesDifferentReadGroups 0.298s passed
testOpticalDuplicatesTheSameReadGroup 0.298s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[0](RUNID:7:1203:2886:82292, RUNID:7:1205:3886:16834) 0.306s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[10](RUNID:7:1203:6886:16756, RUNID:7:1203:4886:26756) 0.292s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[11](RUNID:7:1203:2886:34756, RUNID:7:1203:2886:36756) 0.322s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[12](RUNID:7:1203:2886:35756, RUNID:7:1203:2886:36756) 0.301s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[13](RUNID:7:1203:2886:37756, RUNID:7:1203:2886:36756) 0.297s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[14](RUNID:7:1203:2886:38756, RUNID:7:1203:2886:36756) 0.312s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[15](HK3T5CCXX160204:3:1112:11586:37067, HK3T5CCXX160204:3:1112:11586:32144) 0.302s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[1](RUNID:7:1203:2886:16756, RUNID:7:1205:3886:16756) 0.306s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[2](RUNID:7:1204:2886:16756, RUNID:7:1205:3886:16756) 0.296s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[3](RUNID:7:1205:2886:16756, RUNID:7:1205:3886:16756) 0.295s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[4](RUNID:7:1206:2886:16756, RUNID:7:1205:3886:16756) 0.322s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[5](RUNID:7:1207:2886:16756, RUNID:7:1205:3886:16756) 0.298s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[6](RUNID:7:1203:2886:16756, RUNID:7:1203:4886:26756) 0.296s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[7](RUNID:7:1203:3886:16756, RUNID:7:1203:4886:26756) 0.309s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[8](RUNID:7:1203:4886:16756, RUNID:7:1203:4886:26756) 0.302s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[9](RUNID:7:1203:5886:16756, RUNID:7:1203:4886:26756) 0.299s passed
testPathologicalOrderingAtTheSamePosition 0.300s passed
testReadSameStartPositionOrientationOverride 0.297s passed
testReadsHaveSameStartPositionButDifferentChromosomeNonEquivalence 0.328s passed
testSecondEndIsBeforeFirstInCoordinate 0.303s passed
testSingleMappedFragment 0.299s passed
testSingleMappedFragmentAndSingleMappedPair 0.310s passed
testSingleMappedFragmentAndTwoMappedPairs 0.295s passed
testSingleMappedPair 0.302s passed
testSingleUnmappedFragment 0.292s passed
testSingleUnmappedPair 0.307s passed
testStackOverFlowPairSetSwap 0.293s passed
testSupplementaryReadUnmappedMate 0.296s passed
testThreeGroupsOnDifferentChromosomesOfThreeMappedPairs 0.309s passed
testThreeMappedPairs 0.302s passed
testThreeMappedPairsWithMatchingSecondMate 0.295s passed
testTwoGroupsOnDifferentChromosomesOfThreeMappedPairs 0.295s passed
testTwoGroupsOnDifferentChromosomesOfTwoFragments 0.319s passed
testTwoGroupsOnDifferentChromosomesOfTwoMappedPairs 0.313s passed
testTwoMappedFragments 0.290s passed
testTwoMappedPairWithSamePosition 0.298s passed
testTwoMappedPairWithSamePositionDifferentStrands 0.300s passed
testTwoMappedPairWithSamePositionDifferentStrands2 0.297s passed
testTwoMappedPairs 0.309s passed
testTwoMappedPairsAndMappedSecondaryFragment 0.307s passed
testTwoMappedPairsAndTerminalUnmappedFragment 0.290s passed
testTwoMappedPairsAndTerminalUnmappedPair 0.291s passed
testTwoMappedPairsMatesSoftClipped 0.301s passed
testTwoMappedPairsWithOppositeOrientations 0.302s passed
testTwoMappedPairsWithOppositeOrientationsNumberTwo 0.292s passed
testTwoMappedPairsWithSoftClipping 0.292s passed
testTwoMappedPairsWithSoftClippingBoth 0.303s passed
testTwoMappedPairsWithSoftClippingFirstOfPairOnly 0.306s passed
testTwoMappedPairsWithSoftClippingFirstOfPairOnlyNoMateCigar 0.294s passed
testTwoMappedPairsWithSupplementaryReads[0](true, true, true) 0.305s passed
testTwoMappedPairsWithSupplementaryReads[1](true, false, true) 0.292s passed
testTwoMappedPairsWithSupplementaryReads[2](false, true, true) 0.298s passed
testTwoMappedPairsWithSupplementaryReads[3](true, true, false) 0.301s passed
testTwoMappedPairsWithSupplementaryReads[4](true, false, false) 0.298s passed
testTwoMappedPairsWithSupplementaryReads[5](false, true, false) 0.293s passed
testTwoUnmappedFragments 0.289s passed

Standard error

[May 27, 2025 at 4:00:19 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:19 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:20 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:21 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:22 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
16:00:22.771 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:22.771 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) vf5385f1-SNAPSHOT
16:00:22.771 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
16:00:22.771 INFO  MarkDuplicatesSpark - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:00:22.771 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:00:22.771 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 4:00:22 PM GMT
16:00:22.771 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:22.771 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:22.772 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:00:22.772 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
16:00:22.772 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
16:00:22.772 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:00:22.772 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:00:22.772 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:00:22.772 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:00:22.772 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
16:00:22.772 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
16:00:22.772 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
16:00:22.772 INFO  MarkDuplicatesSpark - Requester pays: disabled
16:00:22.772 INFO  MarkDuplicatesSpark - Initializing engine
16:00:22.772 INFO  MarkDuplicatesSpark - Done initializing engine
16:00:22.772 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
16:00:22.775 INFO  MemoryStore - Block broadcast_1337 stored as values in memory (estimated size 305.5 KiB, free 1898.4 MiB)
16:00:22.781 INFO  MemoryStore - Block broadcast_1337_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1898.4 MiB)
16:00:22.781 INFO  BlockManagerInfo - Added broadcast_1337_piece0 in memory on localhost:41411 (size: 64.0 KiB, free: 1918.7 MiB)
16:00:22.782 INFO  SparkContext - Created broadcast 1337 from newAPIHadoopFile at PathSplitSource.java:96
16:00:22.802 INFO  MemoryStore - Block broadcast_1338 stored as values in memory (estimated size 305.5 KiB, free 1898.1 MiB)
16:00:22.812 INFO  MemoryStore - Block broadcast_1338_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1898.0 MiB)
16:00:22.813 INFO  BlockManagerInfo - Added broadcast_1338_piece0 in memory on localhost:41411 (size: 64.0 KiB, free: 1918.6 MiB)
16:00:22.813 INFO  SparkContext - Created broadcast 1338 from newAPIHadoopFile at PathSplitSource.java:96
16:00:22.845 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
16:00:22.846 INFO  FileInputFormat - Total input files to process : 1
16:00:22.846 INFO  DAGScheduler - Registering RDD 3396 (mapToPair at SparkUtils.java:161) as input to shuffle 97
16:00:22.847 INFO  DAGScheduler - Got job 413 (collect at SparkUtils.java:205) with 1 output partitions
16:00:22.847 INFO  DAGScheduler - Final stage: ResultStage 721 (collect at SparkUtils.java:205)
16:00:22.847 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 720)
16:00:22.847 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 720)
16:00:22.847 INFO  DAGScheduler - Submitting ShuffleMapStage 720 (MapPartitionsRDD[3396] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:22.864 INFO  MemoryStore - Block broadcast_1339 stored as values in memory (estimated size 459.2 KiB, free 1897.6 MiB)
16:00:22.866 INFO  MemoryStore - Block broadcast_1339_piece0 stored as bytes in memory (estimated size 201.4 KiB, free 1897.4 MiB)
16:00:22.867 INFO  BlockManagerInfo - Added broadcast_1339_piece0 in memory on localhost:41411 (size: 201.4 KiB, free: 1918.4 MiB)
16:00:22.867 INFO  SparkContext - Created broadcast 1339 from broadcast at DAGScheduler.scala:1580
16:00:22.867 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))
16:00:22.867 INFO  TaskSchedulerImpl - Adding task set 720.0 with 1 tasks resource profile 0
16:00:22.868 INFO  TaskSetManager - Starting task 0.0 in stage 720.0 (TID 650) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9650 bytes) 
16:00:22.869 INFO  Executor - Running task 0.0 in stage 720.0 (TID 650)
16:00:22.897 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug.bam:0+1507
16:00:22.902 INFO  Executor - Finished task 0.0 in stage 720.0 (TID 650). 1148 bytes result sent to driver
16:00:22.902 INFO  TaskSetManager - Finished task 0.0 in stage 720.0 (TID 650) in 34 ms on localhost (executor driver) (1/1)
16:00:22.902 INFO  TaskSchedulerImpl - Removed TaskSet 720.0, whose tasks have all completed, from pool 
16:00:22.902 INFO  DAGScheduler - ShuffleMapStage 720 (mapToPair at SparkUtils.java:161) finished in 0.054 s
16:00:22.902 INFO  DAGScheduler - looking for newly runnable stages
16:00:22.903 INFO  DAGScheduler - running: HashSet()
16:00:22.903 INFO  DAGScheduler - waiting: HashSet(ResultStage 721)
16:00:22.903 INFO  DAGScheduler - failed: HashSet()
16:00:22.903 INFO  DAGScheduler - Submitting ResultStage 721 (MapPartitionsRDD[3399] at mapPartitions at SparkUtils.java:188), which has no missing parents
16:00:22.904 INFO  MemoryStore - Block broadcast_1340 stored as values in memory (estimated size 7.4 KiB, free 1897.4 MiB)
16:00:22.904 INFO  MemoryStore - Block broadcast_1340_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1897.4 MiB)
16:00:22.904 INFO  BlockManagerInfo - Added broadcast_1340_piece0 in memory on localhost:41411 (size: 4.1 KiB, free: 1918.4 MiB)
16:00:22.905 INFO  SparkContext - Created broadcast 1340 from broadcast at DAGScheduler.scala:1580
16:00:22.905 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))
16:00:22.905 INFO  TaskSchedulerImpl - Adding task set 721.0 with 1 tasks resource profile 0
16:00:22.905 INFO  TaskSetManager - Starting task 0.0 in stage 721.0 (TID 651) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:22.906 INFO  Executor - Running task 0.0 in stage 721.0 (TID 651)
16:00:22.907 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
16:00:22.907 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:22.910 INFO  Executor - Finished task 0.0 in stage 721.0 (TID 651). 2238 bytes result sent to driver
16:00:22.910 INFO  TaskSetManager - Finished task 0.0 in stage 721.0 (TID 651) in 5 ms on localhost (executor driver) (1/1)
16:00:22.910 INFO  TaskSchedulerImpl - Removed TaskSet 721.0, whose tasks have all completed, from pool 
16:00:22.911 INFO  DAGScheduler - ResultStage 721 (collect at SparkUtils.java:205) finished in 0.007 s
16:00:22.911 INFO  DAGScheduler - Job 413 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:22.911 INFO  TaskSchedulerImpl - Killing all running tasks in stage 721: Stage finished
16:00:22.911 INFO  DAGScheduler - Job 413 finished: collect at SparkUtils.java:205, took 0.065522 s
16:00:22.915 INFO  MemoryStore - Block broadcast_1341 stored as values in memory (estimated size 1632.0 B, free 1897.4 MiB)
16:00:22.916 INFO  MemoryStore - Block broadcast_1341_piece0 stored as bytes in memory (estimated size 145.0 B, free 1897.4 MiB)
16:00:22.916 INFO  BlockManagerInfo - Added broadcast_1341_piece0 in memory on localhost:41411 (size: 145.0 B, free: 1918.4 MiB)
16:00:22.916 INFO  SparkContext - Created broadcast 1341 from broadcast at MarkDuplicatesSparkUtils.java:126
16:00:22.917 INFO  MemoryStore - Block broadcast_1342 stored as values in memory (estimated size 304.0 B, free 1897.4 MiB)
16:00:22.917 INFO  MemoryStore - Block broadcast_1342_piece0 stored as bytes in memory (estimated size 37.0 B, free 1897.4 MiB)
16:00:22.917 INFO  BlockManagerInfo - Added broadcast_1342_piece0 in memory on localhost:41411 (size: 37.0 B, free: 1918.4 MiB)
16:00:22.917 INFO  SparkContext - Created broadcast 1342 from broadcast at MarkDuplicatesSparkUtils.java:127
16:00:22.932 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
16:00:22.933 INFO  DAGScheduler - Registering RDD 3408 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 100
16:00:22.933 INFO  DAGScheduler - Registering RDD 3412 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 99
16:00:22.933 INFO  DAGScheduler - Registering RDD 3416 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 98
16:00:22.933 INFO  DAGScheduler - Got job 414 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
16:00:22.933 INFO  DAGScheduler - Final stage: ResultStage 726 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
16:00:22.933 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 725)
16:00:22.933 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 725)
16:00:22.934 INFO  DAGScheduler - Submitting ShuffleMapStage 723 (MapPartitionsRDD[3408] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
16:00:22.934 INFO  MemoryStore - Block broadcast_1343 stored as values in memory (estimated size 24.2 KiB, free 1897.3 MiB)
16:00:22.935 INFO  MemoryStore - Block broadcast_1343_piece0 stored as bytes in memory (estimated size 12.6 KiB, free 1897.3 MiB)
16:00:22.935 INFO  BlockManagerInfo - Added broadcast_1343_piece0 in memory on localhost:41411 (size: 12.6 KiB, free: 1918.4 MiB)
16:00:22.935 INFO  SparkContext - Created broadcast 1343 from broadcast at DAGScheduler.scala:1580
16:00:22.935 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))
16:00:22.936 INFO  TaskSchedulerImpl - Adding task set 723.0 with 1 tasks resource profile 0
16:00:22.936 INFO  TaskSetManager - Starting task 0.0 in stage 723.0 (TID 652) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
16:00:22.936 INFO  Executor - Running task 0.0 in stage 723.0 (TID 652)
16:00:22.938 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
16:00:22.938 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:22.941 INFO  Executor - Finished task 0.0 in stage 723.0 (TID 652). 1922 bytes result sent to driver
16:00:22.941 INFO  TaskSetManager - Finished task 0.0 in stage 723.0 (TID 652) in 5 ms on localhost (executor driver) (1/1)
16:00:22.941 INFO  TaskSchedulerImpl - Removed TaskSet 723.0, whose tasks have all completed, from pool 
16:00:22.942 INFO  DAGScheduler - ShuffleMapStage 723 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.008 s
16:00:22.942 INFO  DAGScheduler - looking for newly runnable stages
16:00:22.942 INFO  DAGScheduler - running: HashSet()
16:00:22.942 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 724, ShuffleMapStage 725, ResultStage 726)
16:00:22.942 INFO  DAGScheduler - failed: HashSet()
16:00:22.942 INFO  DAGScheduler - Submitting ShuffleMapStage 724 (MapPartitionsRDD[3412] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
16:00:22.943 INFO  MemoryStore - Block broadcast_1344 stored as values in memory (estimated size 28.3 KiB, free 1897.3 MiB)
16:00:22.943 INFO  MemoryStore - Block broadcast_1344_piece0 stored as bytes in memory (estimated size 14.8 KiB, free 1897.3 MiB)
16:00:22.943 INFO  BlockManagerInfo - Added broadcast_1344_piece0 in memory on localhost:41411 (size: 14.8 KiB, free: 1918.4 MiB)
16:00:22.944 INFO  SparkContext - Created broadcast 1344 from broadcast at DAGScheduler.scala:1580
16:00:22.944 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))
16:00:22.944 INFO  TaskSchedulerImpl - Adding task set 724.0 with 1 tasks resource profile 0
16:00:22.945 INFO  TaskSetManager - Starting task 0.0 in stage 724.0 (TID 653) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
16:00:22.945 INFO  Executor - Running task 0.0 in stage 724.0 (TID 653)
16:00:22.946 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
16:00:22.946 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:22.950 INFO  Executor - Finished task 0.0 in stage 724.0 (TID 653). 1922 bytes result sent to driver
16:00:22.950 INFO  TaskSetManager - Finished task 0.0 in stage 724.0 (TID 653) in 5 ms on localhost (executor driver) (1/1)
16:00:22.950 INFO  DAGScheduler - ShuffleMapStage 724 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.008 s
16:00:22.950 INFO  DAGScheduler - looking for newly runnable stages
16:00:22.950 INFO  DAGScheduler - running: HashSet()
16:00:22.950 INFO  TaskSchedulerImpl - Removed TaskSet 724.0, whose tasks have all completed, from pool 
16:00:22.950 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 725, ResultStage 726)
16:00:22.950 INFO  DAGScheduler - failed: HashSet()
16:00:22.950 INFO  DAGScheduler - Submitting ShuffleMapStage 725 (MapPartitionsRDD[3416] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
16:00:22.951 INFO  MemoryStore - Block broadcast_1345 stored as values in memory (estimated size 19.0 KiB, free 1897.3 MiB)
16:00:22.952 INFO  MemoryStore - Block broadcast_1345_piece0 stored as bytes in memory (estimated size 9.7 KiB, free 1897.2 MiB)
16:00:22.952 INFO  BlockManagerInfo - Added broadcast_1345_piece0 in memory on localhost:41411 (size: 9.7 KiB, free: 1918.4 MiB)
16:00:22.952 INFO  SparkContext - Created broadcast 1345 from broadcast at DAGScheduler.scala:1580
16:00:22.952 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))
16:00:22.952 INFO  TaskSchedulerImpl - Adding task set 725.0 with 1 tasks resource profile 0
16:00:22.953 INFO  TaskSetManager - Starting task 0.0 in stage 725.0 (TID 654) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:22.953 INFO  Executor - Running task 0.0 in stage 725.0 (TID 654)
16:00:22.955 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
16:00:22.955 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:22.957 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
16:00:22.957 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:22.958 INFO  Executor - Finished task 0.0 in stage 725.0 (TID 654). 1922 bytes result sent to driver
16:00:22.958 INFO  TaskSetManager - Finished task 0.0 in stage 725.0 (TID 654) in 5 ms on localhost (executor driver) (1/1)
16:00:22.959 INFO  TaskSchedulerImpl - Removed TaskSet 725.0, whose tasks have all completed, from pool 
16:00:22.959 INFO  DAGScheduler - ShuffleMapStage 725 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.008 s
16:00:22.959 INFO  DAGScheduler - looking for newly runnable stages
16:00:22.959 INFO  DAGScheduler - running: HashSet()
16:00:22.959 INFO  DAGScheduler - waiting: HashSet(ResultStage 726)
16:00:22.959 INFO  DAGScheduler - failed: HashSet()
16:00:22.959 INFO  DAGScheduler - Submitting ResultStage 726 (MapPartitionsRDD[3418] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
16:00:22.960 INFO  MemoryStore - Block broadcast_1346 stored as values in memory (estimated size 20.2 KiB, free 1897.2 MiB)
16:00:22.960 INFO  MemoryStore - Block broadcast_1346_piece0 stored as bytes in memory (estimated size 10.6 KiB, free 1897.2 MiB)
16:00:22.960 INFO  BlockManagerInfo - Added broadcast_1346_piece0 in memory on localhost:41411 (size: 10.6 KiB, free: 1918.4 MiB)
16:00:22.961 INFO  SparkContext - Created broadcast 1346 from broadcast at DAGScheduler.scala:1580
16:00:22.961 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))
16:00:22.961 INFO  TaskSchedulerImpl - Adding task set 726.0 with 1 tasks resource profile 0
16:00:22.961 INFO  TaskSetManager - Starting task 0.0 in stage 726.0 (TID 655) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:22.962 INFO  Executor - Running task 0.0 in stage 726.0 (TID 655)
16:00:22.964 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
16:00:22.964 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:22.966 INFO  Executor - Finished task 0.0 in stage 726.0 (TID 655). 1944 bytes result sent to driver
16:00:22.966 INFO  TaskSetManager - Finished task 0.0 in stage 726.0 (TID 655) in 5 ms on localhost (executor driver) (1/1)
16:00:22.967 INFO  TaskSchedulerImpl - Removed TaskSet 726.0, whose tasks have all completed, from pool 
16:00:22.967 INFO  DAGScheduler - ResultStage 726 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.008 s
16:00:22.967 INFO  DAGScheduler - Job 414 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:22.967 INFO  TaskSchedulerImpl - Killing all running tasks in stage 726: Stage finished
16:00:22.967 INFO  DAGScheduler - Job 414 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.034751 s
16:00:22.977 INFO  MemoryStore - Block broadcast_1347 stored as values in memory (estimated size 20.3 KiB, free 1897.2 MiB)
16:00:22.978 INFO  MemoryStore - Block broadcast_1347_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1897.2 MiB)
16:00:22.978 INFO  BlockManagerInfo - Added broadcast_1347_piece0 in memory on localhost:41411 (size: 1850.0 B, free: 1918.4 MiB)
16:00:22.978 INFO  SparkContext - Created broadcast 1347 from broadcast at ReadsSparkSink.java:133
16:00:22.979 INFO  MemoryStore - Block broadcast_1348 stored as values in memory (estimated size 20.4 KiB, free 1897.2 MiB)
16:00:22.979 INFO  MemoryStore - Block broadcast_1348_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1897.2 MiB)
16:00:22.979 INFO  BlockManagerInfo - Added broadcast_1348_piece0 in memory on localhost:41411 (size: 1850.0 B, free: 1918.4 MiB)
16:00:22.980 INFO  SparkContext - Created broadcast 1348 from broadcast at BamSink.java:76
16:00:22.981 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
16:00:22.981 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:22.981 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:22.993 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
16:00:22.993 INFO  DAGScheduler - Registering RDD 3420 (mapToPair at SparkUtils.java:161) as input to shuffle 101
16:00:22.994 INFO  DAGScheduler - Got job 415 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
16:00:22.994 INFO  DAGScheduler - Final stage: ResultStage 731 (runJob at SparkHadoopWriter.scala:83)
16:00:22.994 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 730)
16:00:22.994 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 730)
16:00:22.994 INFO  DAGScheduler - Submitting ShuffleMapStage 730 (MapPartitionsRDD[3420] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:22.995 INFO  MemoryStore - Block broadcast_1349 stored as values in memory (estimated size 18.1 KiB, free 1897.2 MiB)
16:00:22.996 INFO  MemoryStore - Block broadcast_1349_piece0 stored as bytes in memory (estimated size 9.5 KiB, free 1897.1 MiB)
16:00:22.996 INFO  BlockManagerInfo - Added broadcast_1349_piece0 in memory on localhost:41411 (size: 9.5 KiB, free: 1918.3 MiB)
16:00:22.996 INFO  SparkContext - Created broadcast 1349 from broadcast at DAGScheduler.scala:1580
16:00:22.996 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))
16:00:22.996 INFO  TaskSchedulerImpl - Adding task set 730.0 with 1 tasks resource profile 0
16:00:22.997 INFO  TaskSetManager - Starting task 0.0 in stage 730.0 (TID 656) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:22.997 INFO  Executor - Running task 0.0 in stage 730.0 (TID 656)
16:00:22.999 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
16:00:22.999 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.001 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
16:00:23.001 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.003 INFO  Executor - Finished task 0.0 in stage 730.0 (TID 656). 1922 bytes result sent to driver
16:00:23.003 INFO  TaskSetManager - Finished task 0.0 in stage 730.0 (TID 656) in 6 ms on localhost (executor driver) (1/1)
16:00:23.003 INFO  TaskSchedulerImpl - Removed TaskSet 730.0, whose tasks have all completed, from pool 
16:00:23.003 INFO  DAGScheduler - ShuffleMapStage 730 (mapToPair at SparkUtils.java:161) finished in 0.009 s
16:00:23.004 INFO  DAGScheduler - looking for newly runnable stages
16:00:23.004 INFO  DAGScheduler - running: HashSet()
16:00:23.004 INFO  DAGScheduler - waiting: HashSet(ResultStage 731)
16:00:23.004 INFO  DAGScheduler - failed: HashSet()
16:00:23.004 INFO  DAGScheduler - Submitting ResultStage 731 (MapPartitionsRDD[3425] at mapToPair at BamSink.java:91), which has no missing parents
16:00:23.011 INFO  MemoryStore - Block broadcast_1350 stored as values in memory (estimated size 163.3 KiB, free 1897.0 MiB)
16:00:23.012 INFO  MemoryStore - Block broadcast_1350_piece0 stored as bytes in memory (estimated size 73.4 KiB, free 1896.9 MiB)
16:00:23.013 INFO  BlockManagerInfo - Added broadcast_1350_piece0 in memory on localhost:41411 (size: 73.4 KiB, free: 1918.3 MiB)
16:00:23.013 INFO  SparkContext - Created broadcast 1350 from broadcast at DAGScheduler.scala:1580
16:00:23.013 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))
16:00:23.013 INFO  TaskSchedulerImpl - Adding task set 731.0 with 1 tasks resource profile 0
16:00:23.014 INFO  TaskSetManager - Starting task 0.0 in stage 731.0 (TID 657) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:23.014 INFO  Executor - Running task 0.0 in stage 731.0 (TID 657)
16:00:23.018 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
16:00:23.018 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.020 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
16:00:23.020 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:23.020 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:23.020 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
16:00:23.020 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:23.020 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:23.031 INFO  FileOutputCommitter - Saved output of task 'attempt_20250527160022365438704524605163_3425_r_000000_0' to file:/tmp/local116905632234052656723/markdups8656915357039161220.bam.parts/_temporary/0/task_20250527160022365438704524605163_3425_r_000000
16:00:23.031 INFO  SparkHadoopMapRedUtil - attempt_20250527160022365438704524605163_3425_r_000000_0: Committed. Elapsed time: 0 ms.
16:00:23.031 INFO  Executor - Finished task 0.0 in stage 731.0 (TID 657). 1858 bytes result sent to driver
16:00:23.032 INFO  TaskSetManager - Finished task 0.0 in stage 731.0 (TID 657) in 19 ms on localhost (executor driver) (1/1)
16:00:23.032 INFO  TaskSchedulerImpl - Removed TaskSet 731.0, whose tasks have all completed, from pool 
16:00:23.032 INFO  DAGScheduler - ResultStage 731 (runJob at SparkHadoopWriter.scala:83) finished in 0.027 s
16:00:23.032 INFO  DAGScheduler - Job 415 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:23.032 INFO  TaskSchedulerImpl - Killing all running tasks in stage 731: Stage finished
16:00:23.032 INFO  DAGScheduler - Job 415 finished: runJob at SparkHadoopWriter.scala:83, took 0.039403 s
16:00:23.033 INFO  SparkHadoopWriter - Start to commit write Job job_20250527160022365438704524605163_3425.
16:00:23.036 INFO  SparkHadoopWriter - Write Job job_20250527160022365438704524605163_3425 committed. Elapsed time: 3 ms.
16:00:23.043 INFO  HadoopFileSystemWrapper - Concatenating 3 parts to /tmp/local116905632234052656723/markdups8656915357039161220.bam
16:00:23.046 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/local116905632234052656723/markdups8656915357039161220.bam done
16:00:23.046 INFO  IndexFileMerger - Merging .sbi files in temp directory /tmp/local116905632234052656723/markdups8656915357039161220.bam.parts/ to /tmp/local116905632234052656723/markdups8656915357039161220.bam.sbi
16:00:23.049 INFO  IndexFileMerger - Done merging .sbi files
16:00:23.049 INFO  IndexFileMerger - Merging .bai files in temp directory /tmp/local116905632234052656723/markdups8656915357039161220.bam.parts/ to /tmp/local116905632234052656723/markdups8656915357039161220.bam.bai
16:00:23.051 INFO  IndexFileMerger - Done merging .bai files
16:00:23.052 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 4:00:23 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
16:00:23.069 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:23.069 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) vf5385f1-SNAPSHOT
16:00:23.069 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
16:00:23.069 INFO  MarkDuplicatesSpark - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:00:23.069 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:00:23.069 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 4:00:23 PM GMT
16:00:23.069 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:23.069 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:23.069 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:00:23.069 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
16:00:23.069 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
16:00:23.069 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:00:23.069 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:00:23.069 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:00:23.070 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:00:23.070 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
16:00:23.070 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
16:00:23.070 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
16:00:23.070 INFO  MarkDuplicatesSpark - Requester pays: disabled
16:00:23.070 INFO  MarkDuplicatesSpark - Initializing engine
16:00:23.070 INFO  MarkDuplicatesSpark - Done initializing engine
16:00:23.070 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
16:00:23.072 INFO  MemoryStore - Block broadcast_1351 stored as values in memory (estimated size 305.5 KiB, free 1896.6 MiB)
16:00:23.078 INFO  MemoryStore - Block broadcast_1351_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1896.6 MiB)
16:00:23.078 INFO  BlockManagerInfo - Added broadcast_1351_piece0 in memory on localhost:41411 (size: 64.0 KiB, free: 1918.2 MiB)
16:00:23.079 INFO  SparkContext - Created broadcast 1351 from newAPIHadoopFile at PathSplitSource.java:96
16:00:23.098 INFO  MemoryStore - Block broadcast_1352 stored as values in memory (estimated size 305.5 KiB, free 1896.3 MiB)
16:00:23.105 INFO  MemoryStore - Block broadcast_1352_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1896.2 MiB)
16:00:23.105 INFO  BlockManagerInfo - Added broadcast_1352_piece0 in memory on localhost:41411 (size: 64.0 KiB, free: 1918.1 MiB)
16:00:23.105 INFO  SparkContext - Created broadcast 1352 from newAPIHadoopFile at PathSplitSource.java:96
16:00:23.136 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
16:00:23.137 INFO  FileInputFormat - Total input files to process : 1
16:00:23.137 INFO  DAGScheduler - Registering RDD 3439 (mapToPair at SparkUtils.java:161) as input to shuffle 102
16:00:23.137 INFO  DAGScheduler - Got job 416 (collect at SparkUtils.java:205) with 1 output partitions
16:00:23.137 INFO  DAGScheduler - Final stage: ResultStage 733 (collect at SparkUtils.java:205)
16:00:23.138 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 732)
16:00:23.138 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 732)
16:00:23.138 INFO  DAGScheduler - Submitting ShuffleMapStage 732 (MapPartitionsRDD[3439] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:23.154 INFO  MemoryStore - Block broadcast_1353 stored as values in memory (estimated size 459.2 KiB, free 1895.7 MiB)
16:00:23.157 INFO  MemoryStore - Block broadcast_1353_piece0 stored as bytes in memory (estimated size 201.4 KiB, free 1895.5 MiB)
16:00:23.157 INFO  BlockManagerInfo - Added broadcast_1353_piece0 in memory on localhost:41411 (size: 201.4 KiB, free: 1917.9 MiB)
16:00:23.157 INFO  SparkContext - Created broadcast 1353 from broadcast at DAGScheduler.scala:1580
16:00:23.157 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))
16:00:23.157 INFO  TaskSchedulerImpl - Adding task set 732.0 with 1 tasks resource profile 0
16:00:23.158 INFO  TaskSetManager - Starting task 0.0 in stage 732.0 (TID 658) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9651 bytes) 
16:00:23.158 INFO  Executor - Running task 0.0 in stage 732.0 (TID 658)
16:00:23.186 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug2.bam:0+1856
16:00:23.190 INFO  Executor - Finished task 0.0 in stage 732.0 (TID 658). 1148 bytes result sent to driver
16:00:23.191 INFO  TaskSetManager - Finished task 0.0 in stage 732.0 (TID 658) in 34 ms on localhost (executor driver) (1/1)
16:00:23.191 INFO  TaskSchedulerImpl - Removed TaskSet 732.0, whose tasks have all completed, from pool 
16:00:23.191 INFO  DAGScheduler - ShuffleMapStage 732 (mapToPair at SparkUtils.java:161) finished in 0.053 s
16:00:23.191 INFO  DAGScheduler - looking for newly runnable stages
16:00:23.191 INFO  DAGScheduler - running: HashSet()
16:00:23.191 INFO  DAGScheduler - waiting: HashSet(ResultStage 733)
16:00:23.191 INFO  DAGScheduler - failed: HashSet()
16:00:23.192 INFO  DAGScheduler - Submitting ResultStage 733 (MapPartitionsRDD[3442] at mapPartitions at SparkUtils.java:188), which has no missing parents
16:00:23.192 INFO  MemoryStore - Block broadcast_1354 stored as values in memory (estimated size 7.4 KiB, free 1895.5 MiB)
16:00:23.193 INFO  MemoryStore - Block broadcast_1354_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1895.5 MiB)
16:00:23.193 INFO  BlockManagerInfo - Added broadcast_1354_piece0 in memory on localhost:41411 (size: 4.1 KiB, free: 1917.9 MiB)
16:00:23.193 INFO  SparkContext - Created broadcast 1354 from broadcast at DAGScheduler.scala:1580
16:00:23.193 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))
16:00:23.193 INFO  TaskSchedulerImpl - Adding task set 733.0 with 1 tasks resource profile 0
16:00:23.194 INFO  TaskSetManager - Starting task 0.0 in stage 733.0 (TID 659) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:23.194 INFO  Executor - Running task 0.0 in stage 733.0 (TID 659)
16:00:23.195 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
16:00:23.195 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.197 INFO  Executor - Finished task 0.0 in stage 733.0 (TID 659). 2495 bytes result sent to driver
16:00:23.198 INFO  TaskSetManager - Finished task 0.0 in stage 733.0 (TID 659) in 5 ms on localhost (executor driver) (1/1)
16:00:23.198 INFO  TaskSchedulerImpl - Removed TaskSet 733.0, whose tasks have all completed, from pool 
16:00:23.198 INFO  DAGScheduler - ResultStage 733 (collect at SparkUtils.java:205) finished in 0.006 s
16:00:23.198 INFO  DAGScheduler - Job 416 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:23.198 INFO  TaskSchedulerImpl - Killing all running tasks in stage 733: Stage finished
16:00:23.198 INFO  DAGScheduler - Job 416 finished: collect at SparkUtils.java:205, took 0.061811 s
16:00:23.202 INFO  MemoryStore - Block broadcast_1355 stored as values in memory (estimated size 1632.0 B, free 1895.5 MiB)
16:00:23.203 INFO  MemoryStore - Block broadcast_1355_piece0 stored as bytes in memory (estimated size 145.0 B, free 1895.5 MiB)
16:00:23.203 INFO  BlockManagerInfo - Added broadcast_1355_piece0 in memory on localhost:41411 (size: 145.0 B, free: 1917.9 MiB)
16:00:23.203 INFO  SparkContext - Created broadcast 1355 from broadcast at MarkDuplicatesSparkUtils.java:126
16:00:23.203 INFO  MemoryStore - Block broadcast_1356 stored as values in memory (estimated size 304.0 B, free 1895.5 MiB)
16:00:23.204 INFO  MemoryStore - Block broadcast_1356_piece0 stored as bytes in memory (estimated size 37.0 B, free 1895.5 MiB)
16:00:23.204 INFO  BlockManagerInfo - Added broadcast_1356_piece0 in memory on localhost:41411 (size: 37.0 B, free: 1917.9 MiB)
16:00:23.204 INFO  SparkContext - Created broadcast 1356 from broadcast at MarkDuplicatesSparkUtils.java:127
16:00:23.215 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
16:00:23.216 INFO  DAGScheduler - Registering RDD 3451 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 105
16:00:23.216 INFO  DAGScheduler - Registering RDD 3455 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 104
16:00:23.216 INFO  DAGScheduler - Registering RDD 3459 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 103
16:00:23.216 INFO  DAGScheduler - Got job 417 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
16:00:23.217 INFO  DAGScheduler - Final stage: ResultStage 738 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
16:00:23.217 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 737)
16:00:23.217 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 737)
16:00:23.217 INFO  DAGScheduler - Submitting ShuffleMapStage 735 (MapPartitionsRDD[3451] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
16:00:23.218 INFO  MemoryStore - Block broadcast_1357 stored as values in memory (estimated size 24.2 KiB, free 1895.5 MiB)
16:00:23.218 INFO  MemoryStore - Block broadcast_1357_piece0 stored as bytes in memory (estimated size 12.6 KiB, free 1895.5 MiB)
16:00:23.218 INFO  BlockManagerInfo - Added broadcast_1357_piece0 in memory on localhost:41411 (size: 12.6 KiB, free: 1917.9 MiB)
16:00:23.218 INFO  SparkContext - Created broadcast 1357 from broadcast at DAGScheduler.scala:1580
16:00:23.219 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))
16:00:23.219 INFO  TaskSchedulerImpl - Adding task set 735.0 with 1 tasks resource profile 0
16:00:23.219 INFO  TaskSetManager - Starting task 0.0 in stage 735.0 (TID 660) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
16:00:23.219 INFO  Executor - Running task 0.0 in stage 735.0 (TID 660)
16:00:23.221 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
16:00:23.221 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.224 INFO  Executor - Finished task 0.0 in stage 735.0 (TID 660). 1922 bytes result sent to driver
16:00:23.224 INFO  TaskSetManager - Finished task 0.0 in stage 735.0 (TID 660) in 5 ms on localhost (executor driver) (1/1)
16:00:23.225 INFO  TaskSchedulerImpl - Removed TaskSet 735.0, whose tasks have all completed, from pool 
16:00:23.225 INFO  DAGScheduler - ShuffleMapStage 735 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.008 s
16:00:23.225 INFO  DAGScheduler - looking for newly runnable stages
16:00:23.225 INFO  DAGScheduler - running: HashSet()
16:00:23.225 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 736, ShuffleMapStage 737, ResultStage 738)
16:00:23.225 INFO  DAGScheduler - failed: HashSet()
16:00:23.225 INFO  DAGScheduler - Submitting ShuffleMapStage 736 (MapPartitionsRDD[3455] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
16:00:23.226 INFO  MemoryStore - Block broadcast_1358 stored as values in memory (estimated size 28.3 KiB, free 1895.5 MiB)
16:00:23.226 INFO  MemoryStore - Block broadcast_1358_piece0 stored as bytes in memory (estimated size 14.8 KiB, free 1895.5 MiB)
16:00:23.226 INFO  BlockManagerInfo - Added broadcast_1358_piece0 in memory on localhost:41411 (size: 14.8 KiB, free: 1917.9 MiB)
16:00:23.226 INFO  SparkContext - Created broadcast 1358 from broadcast at DAGScheduler.scala:1580
16:00:23.227 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))
16:00:23.227 INFO  TaskSchedulerImpl - Adding task set 736.0 with 1 tasks resource profile 0
16:00:23.227 INFO  TaskSetManager - Starting task 0.0 in stage 736.0 (TID 661) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
16:00:23.227 INFO  Executor - Running task 0.0 in stage 736.0 (TID 661)
16:00:23.229 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
16:00:23.229 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.232 INFO  Executor - Finished task 0.0 in stage 736.0 (TID 661). 1922 bytes result sent to driver
16:00:23.233 INFO  TaskSetManager - Finished task 0.0 in stage 736.0 (TID 661) in 6 ms on localhost (executor driver) (1/1)
16:00:23.233 INFO  TaskSchedulerImpl - Removed TaskSet 736.0, whose tasks have all completed, from pool 
16:00:23.233 INFO  DAGScheduler - ShuffleMapStage 736 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.008 s
16:00:23.233 INFO  DAGScheduler - looking for newly runnable stages
16:00:23.233 INFO  DAGScheduler - running: HashSet()
16:00:23.233 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 737, ResultStage 738)
16:00:23.233 INFO  DAGScheduler - failed: HashSet()
16:00:23.233 INFO  DAGScheduler - Submitting ShuffleMapStage 737 (MapPartitionsRDD[3459] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
16:00:23.234 INFO  MemoryStore - Block broadcast_1359 stored as values in memory (estimated size 19.0 KiB, free 1895.4 MiB)
16:00:23.234 INFO  MemoryStore - Block broadcast_1359_piece0 stored as bytes in memory (estimated size 9.7 KiB, free 1895.4 MiB)
16:00:23.234 INFO  BlockManagerInfo - Added broadcast_1359_piece0 in memory on localhost:41411 (size: 9.7 KiB, free: 1917.9 MiB)
16:00:23.235 INFO  SparkContext - Created broadcast 1359 from broadcast at DAGScheduler.scala:1580
16:00:23.235 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))
16:00:23.235 INFO  TaskSchedulerImpl - Adding task set 737.0 with 1 tasks resource profile 0
16:00:23.235 INFO  TaskSetManager - Starting task 0.0 in stage 737.0 (TID 662) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:23.235 INFO  Executor - Running task 0.0 in stage 737.0 (TID 662)
16:00:23.237 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
16:00:23.237 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.239 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
16:00:23.239 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.240 INFO  Executor - Finished task 0.0 in stage 737.0 (TID 662). 1879 bytes result sent to driver
16:00:23.240 INFO  TaskSetManager - Finished task 0.0 in stage 737.0 (TID 662) in 5 ms on localhost (executor driver) (1/1)
16:00:23.240 INFO  TaskSchedulerImpl - Removed TaskSet 737.0, whose tasks have all completed, from pool 
16:00:23.240 INFO  DAGScheduler - ShuffleMapStage 737 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.007 s
16:00:23.240 INFO  DAGScheduler - looking for newly runnable stages
16:00:23.241 INFO  DAGScheduler - running: HashSet()
16:00:23.241 INFO  DAGScheduler - waiting: HashSet(ResultStage 738)
16:00:23.241 INFO  DAGScheduler - failed: HashSet()
16:00:23.241 INFO  DAGScheduler - Submitting ResultStage 738 (MapPartitionsRDD[3461] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
16:00:23.241 INFO  MemoryStore - Block broadcast_1360 stored as values in memory (estimated size 20.2 KiB, free 1895.4 MiB)
16:00:23.242 INFO  MemoryStore - Block broadcast_1360_piece0 stored as bytes in memory (estimated size 10.6 KiB, free 1895.4 MiB)
16:00:23.242 INFO  BlockManagerInfo - Added broadcast_1360_piece0 in memory on localhost:41411 (size: 10.6 KiB, free: 1917.9 MiB)
16:00:23.242 INFO  SparkContext - Created broadcast 1360 from broadcast at DAGScheduler.scala:1580
16:00:23.242 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))
16:00:23.242 INFO  TaskSchedulerImpl - Adding task set 738.0 with 1 tasks resource profile 0
16:00:23.243 INFO  TaskSetManager - Starting task 0.0 in stage 738.0 (TID 663) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:23.243 INFO  Executor - Running task 0.0 in stage 738.0 (TID 663)
16:00:23.244 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
16:00:23.244 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.246 INFO  Executor - Finished task 0.0 in stage 738.0 (TID 663). 2010 bytes result sent to driver
16:00:23.246 INFO  TaskSetManager - Finished task 0.0 in stage 738.0 (TID 663) in 3 ms on localhost (executor driver) (1/1)
16:00:23.246 INFO  TaskSchedulerImpl - Removed TaskSet 738.0, whose tasks have all completed, from pool 
16:00:23.246 INFO  DAGScheduler - ResultStage 738 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.005 s
16:00:23.247 INFO  DAGScheduler - Job 417 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:23.247 INFO  TaskSchedulerImpl - Killing all running tasks in stage 738: Stage finished
16:00:23.247 INFO  DAGScheduler - Job 417 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.031167 s
16:00:23.256 INFO  MemoryStore - Block broadcast_1361 stored as values in memory (estimated size 20.3 KiB, free 1895.4 MiB)
16:00:23.257 INFO  MemoryStore - Block broadcast_1361_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1895.4 MiB)
16:00:23.257 INFO  BlockManagerInfo - Added broadcast_1361_piece0 in memory on localhost:41411 (size: 1850.0 B, free: 1917.9 MiB)
16:00:23.257 INFO  SparkContext - Created broadcast 1361 from broadcast at ReadsSparkSink.java:133
16:00:23.258 INFO  MemoryStore - Block broadcast_1362 stored as values in memory (estimated size 20.4 KiB, free 1895.4 MiB)
16:00:23.258 INFO  MemoryStore - Block broadcast_1362_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1895.4 MiB)
16:00:23.258 INFO  BlockManagerInfo - Added broadcast_1362_piece0 in memory on localhost:41411 (size: 1850.0 B, free: 1917.9 MiB)
16:00:23.259 INFO  SparkContext - Created broadcast 1362 from broadcast at BamSink.java:76
16:00:23.260 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
16:00:23.260 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:23.260 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:23.271 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
16:00:23.272 INFO  DAGScheduler - Registering RDD 3463 (mapToPair at SparkUtils.java:161) as input to shuffle 106
16:00:23.272 INFO  DAGScheduler - Got job 418 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
16:00:23.272 INFO  DAGScheduler - Final stage: ResultStage 743 (runJob at SparkHadoopWriter.scala:83)
16:00:23.272 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 742)
16:00:23.272 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 742)
16:00:23.272 INFO  DAGScheduler - Submitting ShuffleMapStage 742 (MapPartitionsRDD[3463] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:23.273 INFO  MemoryStore - Block broadcast_1363 stored as values in memory (estimated size 18.1 KiB, free 1895.3 MiB)
16:00:23.273 INFO  MemoryStore - Block broadcast_1363_piece0 stored as bytes in memory (estimated size 9.5 KiB, free 1895.3 MiB)
16:00:23.273 INFO  BlockManagerInfo - Added broadcast_1363_piece0 in memory on localhost:41411 (size: 9.5 KiB, free: 1917.9 MiB)
16:00:23.274 INFO  SparkContext - Created broadcast 1363 from broadcast at DAGScheduler.scala:1580
16:00:23.274 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))
16:00:23.274 INFO  TaskSchedulerImpl - Adding task set 742.0 with 1 tasks resource profile 0
16:00:23.274 INFO  TaskSetManager - Starting task 0.0 in stage 742.0 (TID 664) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:23.274 INFO  Executor - Running task 0.0 in stage 742.0 (TID 664)
16:00:23.276 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
16:00:23.276 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.278 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
16:00:23.278 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.279 INFO  Executor - Finished task 0.0 in stage 742.0 (TID 664). 1922 bytes result sent to driver
16:00:23.280 INFO  TaskSetManager - Finished task 0.0 in stage 742.0 (TID 664) in 5 ms on localhost (executor driver) (1/1)
16:00:23.280 INFO  TaskSchedulerImpl - Removed TaskSet 742.0, whose tasks have all completed, from pool 
16:00:23.280 INFO  DAGScheduler - ShuffleMapStage 742 (mapToPair at SparkUtils.java:161) finished in 0.008 s
16:00:23.280 INFO  DAGScheduler - looking for newly runnable stages
16:00:23.280 INFO  DAGScheduler - running: HashSet()
16:00:23.280 INFO  DAGScheduler - waiting: HashSet(ResultStage 743)
16:00:23.280 INFO  DAGScheduler - failed: HashSet()
16:00:23.280 INFO  DAGScheduler - Submitting ResultStage 743 (MapPartitionsRDD[3468] at mapToPair at BamSink.java:91), which has no missing parents
16:00:23.286 INFO  MemoryStore - Block broadcast_1364 stored as values in memory (estimated size 163.3 KiB, free 1895.2 MiB)
16:00:23.287 INFO  MemoryStore - Block broadcast_1364_piece0 stored as bytes in memory (estimated size 73.4 KiB, free 1895.1 MiB)
16:00:23.287 INFO  BlockManagerInfo - Added broadcast_1364_piece0 in memory on localhost:41411 (size: 73.4 KiB, free: 1917.8 MiB)
16:00:23.287 INFO  SparkContext - Created broadcast 1364 from broadcast at DAGScheduler.scala:1580
16:00:23.288 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))
16:00:23.288 INFO  TaskSchedulerImpl - Adding task set 743.0 with 1 tasks resource profile 0
16:00:23.288 INFO  TaskSetManager - Starting task 0.0 in stage 743.0 (TID 665) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:23.288 INFO  Executor - Running task 0.0 in stage 743.0 (TID 665)
16:00:23.293 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
16:00:23.293 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:23.296 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
16:00:23.296 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:23.296 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:23.296 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
16:00:23.296 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:23.296 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:23.306 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271600234373651576938373602_3468_r_000000_0' to file:/tmp/local116905632234052656723/markdups4857219897559537849.bam.parts/_temporary/0/task_202505271600234373651576938373602_3468_r_000000
16:00:23.306 INFO  SparkHadoopMapRedUtil - attempt_202505271600234373651576938373602_3468_r_000000_0: Committed. Elapsed time: 0 ms.
16:00:23.307 INFO  Executor - Finished task 0.0 in stage 743.0 (TID 665). 1858 bytes result sent to driver
16:00:23.307 INFO  TaskSetManager - Finished task 0.0 in stage 743.0 (TID 665) in 19 ms on localhost (executor driver) (1/1)
16:00:23.307 INFO  TaskSchedulerImpl - Removed TaskSet 743.0, whose tasks have all completed, from pool 
16:00:23.307 INFO  DAGScheduler - ResultStage 743 (runJob at SparkHadoopWriter.scala:83) finished in 0.027 s
16:00:23.307 INFO  DAGScheduler - Job 418 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:23.307 INFO  TaskSchedulerImpl - Killing all running tasks in stage 743: Stage finished
16:00:23.307 INFO  DAGScheduler - Job 418 finished: runJob at SparkHadoopWriter.scala:83, took 0.036067 s
16:00:23.307 INFO  SparkHadoopWriter - Start to commit write Job job_202505271600234373651576938373602_3468.
16:00:23.310 INFO  SparkHadoopWriter - Write Job job_202505271600234373651576938373602_3468 committed. Elapsed time: 2 ms.
16:00:23.316 INFO  HadoopFileSystemWrapper - Concatenating 3 parts to /tmp/local116905632234052656723/markdups4857219897559537849.bam
16:00:23.318 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/local116905632234052656723/markdups4857219897559537849.bam done
16:00:23.318 INFO  IndexFileMerger - Merging .sbi files in temp directory /tmp/local116905632234052656723/markdups4857219897559537849.bam.parts/ to /tmp/local116905632234052656723/markdups4857219897559537849.bam.sbi
16:00:23.321 INFO  IndexFileMerger - Done merging .sbi files
16:00:23.321 INFO  IndexFileMerger - Merging .bai files in temp directory /tmp/local116905632234052656723/markdups4857219897559537849.bam.parts/ to /tmp/local116905632234052656723/markdups4857219897559537849.bam.bai
16:00:23.323 INFO  IndexFileMerger - Done merging .bai files
16:00:23.324 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 4:00:23 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:23 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:24 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:24 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:24 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:25 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:25 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:26 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:27 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:28 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:28 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:29 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:29 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:29 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:30 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:32 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:32 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:32 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:33 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:33 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:33 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:34 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:36 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:36 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:36 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:37 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:39 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:40 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:40 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:40 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:41 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:41 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:41 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:43 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:44 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:44 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:45 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:47 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:47 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
16:00:47.769 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:47.769 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) vf5385f1-SNAPSHOT
16:00:47.769 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
16:00:47.769 INFO  MarkDuplicatesSpark - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:00:47.769 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:00:47.769 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 4:00:47 PM GMT
16:00:47.770 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:47.770 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:47.770 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:00:47.770 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
16:00:47.770 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
16:00:47.770 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:00:47.770 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:00:47.770 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:00:47.770 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:00:47.770 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
16:00:47.770 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
16:00:47.770 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
16:00:47.770 INFO  MarkDuplicatesSpark - Requester pays: disabled
16:00:47.770 INFO  MarkDuplicatesSpark - Initializing engine
16:00:47.770 INFO  MarkDuplicatesSpark - Done initializing engine
16:00:47.770 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
16:00:47.772 INFO  MemoryStore - Block broadcast_1941 stored as values in memory (estimated size 305.5 KiB, free 1911.7 MiB)
16:00:47.779 INFO  MemoryStore - Block broadcast_1941_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1911.6 MiB)
16:00:47.779 INFO  BlockManagerInfo - Added broadcast_1941_piece0 in memory on localhost:41411 (size: 64.0 KiB, free: 1918.9 MiB)
16:00:47.779 INFO  SparkContext - Created broadcast 1941 from newAPIHadoopFile at PathSplitSource.java:96
16:00:47.800 INFO  MemoryStore - Block broadcast_1942 stored as values in memory (estimated size 305.5 KiB, free 1911.3 MiB)
16:00:47.806 INFO  MemoryStore - Block broadcast_1942_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1911.3 MiB)
16:00:47.806 INFO  BlockManagerInfo - Added broadcast_1942_piece0 in memory on localhost:41411 (size: 64.0 KiB, free: 1918.9 MiB)
16:00:47.806 INFO  SparkContext - Created broadcast 1942 from newAPIHadoopFile at PathSplitSource.java:96
16:00:47.839 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
16:00:47.839 INFO  FileInputFormat - Total input files to process : 1
16:00:47.840 INFO  DAGScheduler - Registering RDD 5360 (mapToPair at SparkUtils.java:161) as input to shuffle 297
16:00:47.840 INFO  DAGScheduler - Got job 549 (collect at SparkUtils.java:205) with 1 output partitions
16:00:47.840 INFO  DAGScheduler - Final stage: ResultStage 1205 (collect at SparkUtils.java:205)
16:00:47.840 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1204)
16:00:47.840 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1204)
16:00:47.840 INFO  DAGScheduler - Submitting ShuffleMapStage 1204 (MapPartitionsRDD[5360] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:47.866 INFO  MemoryStore - Block broadcast_1943 stored as values in memory (estimated size 492.6 KiB, free 1910.8 MiB)
16:00:47.868 INFO  MemoryStore - Block broadcast_1943_piece0 stored as bytes in memory (estimated size 208.9 KiB, free 1910.6 MiB)
16:00:47.868 INFO  BlockManagerInfo - Added broadcast_1943_piece0 in memory on localhost:41411 (size: 208.9 KiB, free: 1918.6 MiB)
16:00:47.869 INFO  SparkContext - Created broadcast 1943 from broadcast at DAGScheduler.scala:1580
16:00:47.869 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))
16:00:47.869 INFO  TaskSchedulerImpl - Adding task set 1204.0 with 1 tasks resource profile 0
16:00:47.869 INFO  TaskSetManager - Starting task 0.0 in stage 1204.0 (TID 1036) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9674 bytes) 
16:00:47.869 INFO  Executor - Running task 0.0 in stage 1204.0 (TID 1036)
16:00:47.902 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/example.chr1.1-1K.unmarkedDups.bam:0+13412
16:00:47.908 INFO  Executor - Finished task 0.0 in stage 1204.0 (TID 1036). 1148 bytes result sent to driver
16:00:47.908 INFO  TaskSetManager - Finished task 0.0 in stage 1204.0 (TID 1036) in 39 ms on localhost (executor driver) (1/1)
16:00:47.908 INFO  TaskSchedulerImpl - Removed TaskSet 1204.0, whose tasks have all completed, from pool 
16:00:47.909 INFO  DAGScheduler - ShuffleMapStage 1204 (mapToPair at SparkUtils.java:161) finished in 0.069 s
16:00:47.909 INFO  DAGScheduler - looking for newly runnable stages
16:00:47.909 INFO  DAGScheduler - running: HashSet()
16:00:47.909 INFO  DAGScheduler - waiting: HashSet(ResultStage 1205)
16:00:47.909 INFO  DAGScheduler - failed: HashSet()
16:00:47.909 INFO  DAGScheduler - Submitting ResultStage 1205 (MapPartitionsRDD[5363] at mapPartitions at SparkUtils.java:188), which has no missing parents
16:00:47.909 INFO  MemoryStore - Block broadcast_1944 stored as values in memory (estimated size 7.4 KiB, free 1910.6 MiB)
16:00:47.910 INFO  MemoryStore - Block broadcast_1944_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1910.6 MiB)
16:00:47.910 INFO  BlockManagerInfo - Added broadcast_1944_piece0 in memory on localhost:41411 (size: 4.1 KiB, free: 1918.6 MiB)
16:00:47.910 INFO  SparkContext - Created broadcast 1944 from broadcast at DAGScheduler.scala:1580
16:00:47.910 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))
16:00:47.910 INFO  TaskSchedulerImpl - Adding task set 1205.0 with 1 tasks resource profile 0
16:00:47.911 INFO  TaskSetManager - Starting task 0.0 in stage 1205.0 (TID 1037) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:47.911 INFO  Executor - Running task 0.0 in stage 1205.0 (TID 1037)
16:00:47.912 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
16:00:47.912 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:47.914 INFO  Executor - Finished task 0.0 in stage 1205.0 (TID 1037). 2329 bytes result sent to driver
16:00:47.915 INFO  TaskSetManager - Finished task 0.0 in stage 1205.0 (TID 1037) in 4 ms on localhost (executor driver) (1/1)
16:00:47.915 INFO  TaskSchedulerImpl - Removed TaskSet 1205.0, whose tasks have all completed, from pool 
16:00:47.915 INFO  DAGScheduler - ResultStage 1205 (collect at SparkUtils.java:205) finished in 0.006 s
16:00:47.915 INFO  DAGScheduler - Job 549 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:47.915 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1205: Stage finished
16:00:47.915 INFO  DAGScheduler - Job 549 finished: collect at SparkUtils.java:205, took 0.076018 s
16:00:47.919 INFO  MemoryStore - Block broadcast_1945 stored as values in memory (estimated size 7.8 KiB, free 1910.6 MiB)
16:00:47.919 INFO  MemoryStore - Block broadcast_1945_piece0 stored as bytes in memory (estimated size 540.0 B, free 1910.6 MiB)
16:00:47.919 INFO  BlockManagerInfo - Added broadcast_1945_piece0 in memory on localhost:41411 (size: 540.0 B, free: 1918.6 MiB)
16:00:47.919 INFO  SparkContext - Created broadcast 1945 from broadcast at MarkDuplicatesSparkUtils.java:126
16:00:47.920 INFO  MemoryStore - Block broadcast_1946 stored as values in memory (estimated size 2.6 KiB, free 1910.6 MiB)
16:00:47.920 INFO  MemoryStore - Block broadcast_1946_piece0 stored as bytes in memory (estimated size 209.0 B, free 1910.6 MiB)
16:00:47.920 INFO  BlockManagerInfo - Added broadcast_1946_piece0 in memory on localhost:41411 (size: 209.0 B, free: 1918.6 MiB)
16:00:47.920 INFO  SparkContext - Created broadcast 1946 from broadcast at MarkDuplicatesSparkUtils.java:127
16:00:47.934 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
16:00:47.934 INFO  DAGScheduler - Registering RDD 5372 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 300
16:00:47.934 INFO  DAGScheduler - Registering RDD 5376 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 299
16:00:47.934 INFO  DAGScheduler - Registering RDD 5380 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 298
16:00:47.935 INFO  DAGScheduler - Got job 550 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
16:00:47.935 INFO  DAGScheduler - Final stage: ResultStage 1210 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
16:00:47.935 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1209)
16:00:47.935 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1209)
16:00:47.935 INFO  DAGScheduler - Submitting ShuffleMapStage 1207 (MapPartitionsRDD[5372] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
16:00:47.936 INFO  MemoryStore - Block broadcast_1947 stored as values in memory (estimated size 57.6 KiB, free 1910.5 MiB)
16:00:47.936 INFO  MemoryStore - Block broadcast_1947_piece0 stored as bytes in memory (estimated size 19.8 KiB, free 1910.5 MiB)
16:00:47.936 INFO  BlockManagerInfo - Added broadcast_1947_piece0 in memory on localhost:41411 (size: 19.8 KiB, free: 1918.6 MiB)
16:00:47.937 INFO  SparkContext - Created broadcast 1947 from broadcast at DAGScheduler.scala:1580
16:00:47.937 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))
16:00:47.937 INFO  TaskSchedulerImpl - Adding task set 1207.0 with 1 tasks resource profile 0
16:00:47.937 INFO  TaskSetManager - Starting task 0.0 in stage 1207.0 (TID 1038) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
16:00:47.937 INFO  Executor - Running task 0.0 in stage 1207.0 (TID 1038)
16:00:47.939 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
16:00:47.939 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:47.943 INFO  Executor - Finished task 0.0 in stage 1207.0 (TID 1038). 1922 bytes result sent to driver
16:00:47.943 INFO  TaskSetManager - Finished task 0.0 in stage 1207.0 (TID 1038) in 6 ms on localhost (executor driver) (1/1)
16:00:47.943 INFO  TaskSchedulerImpl - Removed TaskSet 1207.0, whose tasks have all completed, from pool 
16:00:47.943 INFO  DAGScheduler - ShuffleMapStage 1207 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.008 s
16:00:47.943 INFO  DAGScheduler - looking for newly runnable stages
16:00:47.943 INFO  DAGScheduler - running: HashSet()
16:00:47.943 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1208, ShuffleMapStage 1209, ResultStage 1210)
16:00:47.943 INFO  DAGScheduler - failed: HashSet()
16:00:47.943 INFO  DAGScheduler - Submitting ShuffleMapStage 1208 (MapPartitionsRDD[5376] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
16:00:47.944 INFO  MemoryStore - Block broadcast_1948 stored as values in memory (estimated size 61.7 KiB, free 1910.4 MiB)
16:00:47.945 INFO  MemoryStore - Block broadcast_1948_piece0 stored as bytes in memory (estimated size 22.0 KiB, free 1910.4 MiB)
16:00:47.945 INFO  BlockManagerInfo - Added broadcast_1948_piece0 in memory on localhost:41411 (size: 22.0 KiB, free: 1918.6 MiB)
16:00:47.945 INFO  SparkContext - Created broadcast 1948 from broadcast at DAGScheduler.scala:1580
16:00:47.945 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))
16:00:47.945 INFO  TaskSchedulerImpl - Adding task set 1208.0 with 1 tasks resource profile 0
16:00:47.946 INFO  TaskSetManager - Starting task 0.0 in stage 1208.0 (TID 1039) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
16:00:47.946 INFO  Executor - Running task 0.0 in stage 1208.0 (TID 1039)
16:00:47.947 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
16:00:47.947 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:47.952 INFO  Executor - Finished task 0.0 in stage 1208.0 (TID 1039). 1922 bytes result sent to driver
16:00:47.952 INFO  TaskSetManager - Finished task 0.0 in stage 1208.0 (TID 1039) in 6 ms on localhost (executor driver) (1/1)
16:00:47.952 INFO  TaskSchedulerImpl - Removed TaskSet 1208.0, whose tasks have all completed, from pool 
16:00:47.952 INFO  DAGScheduler - ShuffleMapStage 1208 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.008 s
16:00:47.952 INFO  DAGScheduler - looking for newly runnable stages
16:00:47.952 INFO  DAGScheduler - running: HashSet()
16:00:47.952 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1209, ResultStage 1210)
16:00:47.952 INFO  DAGScheduler - failed: HashSet()
16:00:47.952 INFO  DAGScheduler - Submitting ShuffleMapStage 1209 (MapPartitionsRDD[5380] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
16:00:47.953 INFO  MemoryStore - Block broadcast_1949 stored as values in memory (estimated size 52.4 KiB, free 1910.4 MiB)
16:00:47.954 INFO  MemoryStore - Block broadcast_1949_piece0 stored as bytes in memory (estimated size 17.3 KiB, free 1910.3 MiB)
16:00:47.954 INFO  BlockManagerInfo - Added broadcast_1949_piece0 in memory on localhost:41411 (size: 17.3 KiB, free: 1918.6 MiB)
16:00:47.954 INFO  SparkContext - Created broadcast 1949 from broadcast at DAGScheduler.scala:1580
16:00:47.954 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))
16:00:47.954 INFO  TaskSchedulerImpl - Adding task set 1209.0 with 1 tasks resource profile 0
16:00:47.955 INFO  TaskSetManager - Starting task 0.0 in stage 1209.0 (TID 1040) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:47.955 INFO  Executor - Running task 0.0 in stage 1209.0 (TID 1040)
16:00:47.956 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
16:00:47.956 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:47.959 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
16:00:47.959 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:47.960 INFO  Executor - Finished task 0.0 in stage 1209.0 (TID 1040). 1922 bytes result sent to driver
16:00:47.960 INFO  TaskSetManager - Finished task 0.0 in stage 1209.0 (TID 1040) in 6 ms on localhost (executor driver) (1/1)
16:00:47.961 INFO  TaskSchedulerImpl - Removed TaskSet 1209.0, whose tasks have all completed, from pool 
16:00:47.961 INFO  DAGScheduler - ShuffleMapStage 1209 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.008 s
16:00:47.961 INFO  DAGScheduler - looking for newly runnable stages
16:00:47.961 INFO  DAGScheduler - running: HashSet()
16:00:47.961 INFO  DAGScheduler - waiting: HashSet(ResultStage 1210)
16:00:47.961 INFO  DAGScheduler - failed: HashSet()
16:00:47.961 INFO  DAGScheduler - Submitting ResultStage 1210 (MapPartitionsRDD[5382] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
16:00:47.962 INFO  MemoryStore - Block broadcast_1950 stored as values in memory (estimated size 53.6 KiB, free 1910.3 MiB)
16:00:47.962 INFO  MemoryStore - Block broadcast_1950_piece0 stored as bytes in memory (estimated size 18.0 KiB, free 1910.3 MiB)
16:00:47.962 INFO  BlockManagerInfo - Added broadcast_1950_piece0 in memory on localhost:41411 (size: 18.0 KiB, free: 1918.6 MiB)
16:00:47.963 INFO  SparkContext - Created broadcast 1950 from broadcast at DAGScheduler.scala:1580
16:00:47.963 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))
16:00:47.963 INFO  TaskSchedulerImpl - Adding task set 1210.0 with 1 tasks resource profile 0
16:00:47.963 INFO  TaskSetManager - Starting task 0.0 in stage 1210.0 (TID 1041) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:47.963 INFO  Executor - Running task 0.0 in stage 1210.0 (TID 1041)
16:00:47.964 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
16:00:47.965 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:47.966 INFO  Executor - Finished task 0.0 in stage 1210.0 (TID 1041). 2371 bytes result sent to driver
16:00:47.966 INFO  TaskSetManager - Finished task 0.0 in stage 1210.0 (TID 1041) in 3 ms on localhost (executor driver) (1/1)
16:00:47.966 INFO  TaskSchedulerImpl - Removed TaskSet 1210.0, whose tasks have all completed, from pool 
16:00:47.966 INFO  DAGScheduler - ResultStage 1210 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.005 s
16:00:47.966 INFO  DAGScheduler - Job 550 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:47.966 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1210: Stage finished
16:00:47.966 INFO  DAGScheduler - Job 550 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.032619 s
16:00:47.977 INFO  MemoryStore - Block broadcast_1951 stored as values in memory (estimated size 179.4 KiB, free 1910.1 MiB)
16:00:47.978 INFO  MemoryStore - Block broadcast_1951_piece0 stored as bytes in memory (estimated size 7.9 KiB, free 1910.1 MiB)
16:00:47.978 INFO  BlockManagerInfo - Added broadcast_1951_piece0 in memory on localhost:41411 (size: 7.9 KiB, free: 1918.6 MiB)
16:00:47.978 INFO  SparkContext - Created broadcast 1951 from broadcast at ReadsSparkSink.java:133
16:00:47.981 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
16:00:47.982 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:47.982 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:47.993 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
16:00:47.993 INFO  DAGScheduler - Registering RDD 5384 (mapToPair at SparkUtils.java:161) as input to shuffle 301
16:00:47.993 INFO  DAGScheduler - Got job 551 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
16:00:47.993 INFO  DAGScheduler - Final stage: ResultStage 1215 (runJob at SparkHadoopWriter.scala:83)
16:00:47.993 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1214)
16:00:47.993 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1214)
16:00:47.993 INFO  DAGScheduler - Submitting ShuffleMapStage 1214 (MapPartitionsRDD[5384] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:47.994 INFO  MemoryStore - Block broadcast_1952 stored as values in memory (estimated size 51.5 KiB, free 1910.0 MiB)
16:00:47.995 INFO  MemoryStore - Block broadcast_1952_piece0 stored as bytes in memory (estimated size 16.8 KiB, free 1910.0 MiB)
16:00:47.995 INFO  BlockManagerInfo - Added broadcast_1952_piece0 in memory on localhost:41411 (size: 16.8 KiB, free: 1918.5 MiB)
16:00:47.995 INFO  SparkContext - Created broadcast 1952 from broadcast at DAGScheduler.scala:1580
16:00:47.995 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))
16:00:47.995 INFO  TaskSchedulerImpl - Adding task set 1214.0 with 1 tasks resource profile 0
16:00:47.995 INFO  TaskSetManager - Starting task 0.0 in stage 1214.0 (TID 1042) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:47.996 INFO  Executor - Running task 0.0 in stage 1214.0 (TID 1042)
16:00:47.997 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
16:00:47.997 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.000 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
16:00:48.000 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.001 INFO  Executor - Finished task 0.0 in stage 1214.0 (TID 1042). 1922 bytes result sent to driver
16:00:48.002 INFO  TaskSetManager - Finished task 0.0 in stage 1214.0 (TID 1042) in 7 ms on localhost (executor driver) (1/1)
16:00:48.002 INFO  TaskSchedulerImpl - Removed TaskSet 1214.0, whose tasks have all completed, from pool 
16:00:48.002 INFO  DAGScheduler - ShuffleMapStage 1214 (mapToPair at SparkUtils.java:161) finished in 0.009 s
16:00:48.002 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.002 INFO  DAGScheduler - running: HashSet()
16:00:48.002 INFO  DAGScheduler - waiting: HashSet(ResultStage 1215)
16:00:48.002 INFO  DAGScheduler - failed: HashSet()
16:00:48.002 INFO  DAGScheduler - Submitting ResultStage 1215 (MapPartitionsRDD[5390] at saveAsTextFile at SamSink.java:65), which has no missing parents
16:00:48.008 INFO  MemoryStore - Block broadcast_1953 stored as values in memory (estimated size 196.3 KiB, free 1909.8 MiB)
16:00:48.009 INFO  MemoryStore - Block broadcast_1953_piece0 stored as bytes in memory (estimated size 80.5 KiB, free 1909.8 MiB)
16:00:48.010 INFO  BlockManagerInfo - Added broadcast_1953_piece0 in memory on localhost:41411 (size: 80.5 KiB, free: 1918.5 MiB)
16:00:48.010 INFO  SparkContext - Created broadcast 1953 from broadcast at DAGScheduler.scala:1580
16:00:48.010 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))
16:00:48.010 INFO  TaskSchedulerImpl - Adding task set 1215.0 with 1 tasks resource profile 0
16:00:48.010 INFO  TaskSetManager - Starting task 0.0 in stage 1215.0 (TID 1043) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:48.010 INFO  Executor - Running task 0.0 in stage 1215.0 (TID 1043)
16:00:48.014 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
16:00:48.014 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.016 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
16:00:48.016 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:48.016 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:48.022 INFO  FileOutputCommitter - Saved output of task 'attempt_20250527160047805466881959662274_5390_m_000000_0' to file:/tmp/MarkDups12695484567084983924/MarkDups.sam.parts/_temporary/0/task_20250527160047805466881959662274_5390_m_000000
16:00:48.022 INFO  SparkHadoopMapRedUtil - attempt_20250527160047805466881959662274_5390_m_000000_0: Committed. Elapsed time: 0 ms.
16:00:48.023 INFO  Executor - Finished task 0.0 in stage 1215.0 (TID 1043). 1858 bytes result sent to driver
16:00:48.023 INFO  TaskSetManager - Finished task 0.0 in stage 1215.0 (TID 1043) in 13 ms on localhost (executor driver) (1/1)
16:00:48.023 INFO  TaskSchedulerImpl - Removed TaskSet 1215.0, whose tasks have all completed, from pool 
16:00:48.023 INFO  DAGScheduler - ResultStage 1215 (runJob at SparkHadoopWriter.scala:83) finished in 0.021 s
16:00:48.023 INFO  DAGScheduler - Job 551 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:48.023 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1215: Stage finished
16:00:48.023 INFO  DAGScheduler - Job 551 finished: runJob at SparkHadoopWriter.scala:83, took 0.030528 s
16:00:48.023 INFO  SparkHadoopWriter - Start to commit write Job job_20250527160047805466881959662274_5390.
16:00:48.026 INFO  SparkHadoopWriter - Write Job job_20250527160047805466881959662274_5390 committed. Elapsed time: 2 ms.
16:00:48.030 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups12695484567084983924/MarkDups.sam
16:00:48.032 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups12695484567084983924/MarkDups.sam done
16:00:48.033 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 4:00:48 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
16:00:48.051 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:48.051 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) vf5385f1-SNAPSHOT
16:00:48.051 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
16:00:48.051 INFO  MarkDuplicatesSpark - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:00:48.051 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:00:48.051 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 4:00:48 PM GMT
16:00:48.051 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:48.051 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:48.052 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:00:48.052 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
16:00:48.052 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
16:00:48.052 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:00:48.052 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:00:48.052 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:00:48.052 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:00:48.052 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
16:00:48.052 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
16:00:48.052 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
16:00:48.052 INFO  MarkDuplicatesSpark - Requester pays: disabled
16:00:48.052 INFO  MarkDuplicatesSpark - Initializing engine
16:00:48.052 INFO  MarkDuplicatesSpark - Done initializing engine
16:00:48.052 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
16:00:48.054 INFO  MemoryStore - Block broadcast_1954 stored as values in memory (estimated size 305.5 KiB, free 1909.5 MiB)
16:00:48.060 INFO  MemoryStore - Block broadcast_1954_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1909.4 MiB)
16:00:48.060 INFO  BlockManagerInfo - Added broadcast_1954_piece0 in memory on localhost:41411 (size: 64.0 KiB, free: 1918.4 MiB)
16:00:48.061 INFO  SparkContext - Created broadcast 1954 from newAPIHadoopFile at PathSplitSource.java:96
16:00:48.081 INFO  MemoryStore - Block broadcast_1955 stored as values in memory (estimated size 305.5 KiB, free 1909.1 MiB)
16:00:48.087 INFO  MemoryStore - Block broadcast_1955_piece0 stored as bytes in memory (estimated size 64.0 KiB, free 1909.0 MiB)
16:00:48.087 INFO  BlockManagerInfo - Added broadcast_1955_piece0 in memory on localhost:41411 (size: 64.0 KiB, free: 1918.3 MiB)
16:00:48.087 INFO  SparkContext - Created broadcast 1955 from newAPIHadoopFile at PathSplitSource.java:96
16:00:48.118 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
16:00:48.119 INFO  FileInputFormat - Total input files to process : 1
16:00:48.119 INFO  DAGScheduler - Registering RDD 5404 (mapToPair at SparkUtils.java:161) as input to shuffle 302
16:00:48.119 INFO  DAGScheduler - Got job 552 (collect at SparkUtils.java:205) with 1 output partitions
16:00:48.119 INFO  DAGScheduler - Final stage: ResultStage 1217 (collect at SparkUtils.java:205)
16:00:48.119 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1216)
16:00:48.119 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1216)
16:00:48.119 INFO  DAGScheduler - Submitting ShuffleMapStage 1216 (MapPartitionsRDD[5404] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:48.136 INFO  MemoryStore - Block broadcast_1956 stored as values in memory (estimated size 456.1 KiB, free 1908.6 MiB)
16:00:48.139 INFO  MemoryStore - Block broadcast_1956_piece0 stored as bytes in memory (estimated size 200.0 KiB, free 1908.4 MiB)
16:00:48.139 INFO  BlockManagerInfo - Added broadcast_1956_piece0 in memory on localhost:41411 (size: 200.0 KiB, free: 1918.1 MiB)
16:00:48.139 INFO  SparkContext - Created broadcast 1956 from broadcast at DAGScheduler.scala:1580
16:00:48.139 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))
16:00:48.139 INFO  TaskSchedulerImpl - Adding task set 1216.0 with 1 tasks resource profile 0
16:00:48.140 INFO  TaskSetManager - Starting task 0.0 in stage 1216.0 (TID 1044) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9653 bytes) 
16:00:48.140 INFO  Executor - Running task 0.0 in stage 1216.0 (TID 1044)
16:00:48.167 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/optical_dupes.bam:0+678
16:00:48.171 INFO  Executor - Finished task 0.0 in stage 1216.0 (TID 1044). 1148 bytes result sent to driver
16:00:48.171 INFO  TaskSetManager - Finished task 0.0 in stage 1216.0 (TID 1044) in 32 ms on localhost (executor driver) (1/1)
16:00:48.171 INFO  TaskSchedulerImpl - Removed TaskSet 1216.0, whose tasks have all completed, from pool 
16:00:48.172 INFO  DAGScheduler - ShuffleMapStage 1216 (mapToPair at SparkUtils.java:161) finished in 0.053 s
16:00:48.172 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.172 INFO  DAGScheduler - running: HashSet()
16:00:48.172 INFO  DAGScheduler - waiting: HashSet(ResultStage 1217)
16:00:48.172 INFO  DAGScheduler - failed: HashSet()
16:00:48.172 INFO  DAGScheduler - Submitting ResultStage 1217 (MapPartitionsRDD[5407] at mapPartitions at SparkUtils.java:188), which has no missing parents
16:00:48.172 INFO  MemoryStore - Block broadcast_1957 stored as values in memory (estimated size 7.4 KiB, free 1908.4 MiB)
16:00:48.173 INFO  MemoryStore - Block broadcast_1957_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1908.4 MiB)
16:00:48.173 INFO  BlockManagerInfo - Added broadcast_1957_piece0 in memory on localhost:41411 (size: 4.1 KiB, free: 1918.1 MiB)
16:00:48.173 INFO  SparkContext - Created broadcast 1957 from broadcast at DAGScheduler.scala:1580
16:00:48.173 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))
16:00:48.173 INFO  TaskSchedulerImpl - Adding task set 1217.0 with 1 tasks resource profile 0
16:00:48.173 INFO  TaskSetManager - Starting task 0.0 in stage 1217.0 (TID 1045) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:48.173 INFO  Executor - Running task 0.0 in stage 1217.0 (TID 1045)
16:00:48.174 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
16:00:48.174 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.176 INFO  Executor - Finished task 0.0 in stage 1217.0 (TID 1045). 2269 bytes result sent to driver
16:00:48.176 INFO  TaskSetManager - Finished task 0.0 in stage 1217.0 (TID 1045) in 3 ms on localhost (executor driver) (1/1)
16:00:48.176 INFO  TaskSchedulerImpl - Removed TaskSet 1217.0, whose tasks have all completed, from pool 
16:00:48.176 INFO  DAGScheduler - ResultStage 1217 (collect at SparkUtils.java:205) finished in 0.004 s
16:00:48.176 INFO  DAGScheduler - Job 552 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:48.176 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1217: Stage finished
16:00:48.176 INFO  DAGScheduler - Job 552 finished: collect at SparkUtils.java:205, took 0.057825 s
16:00:48.180 INFO  MemoryStore - Block broadcast_1958 stored as values in memory (estimated size 136.0 B, free 1908.4 MiB)
16:00:48.180 INFO  MemoryStore - Block broadcast_1958_piece0 stored as bytes in memory (estimated size 24.0 B, free 1908.4 MiB)
16:00:48.180 INFO  BlockManagerInfo - Added broadcast_1958_piece0 in memory on localhost:41411 (size: 24.0 B, free: 1918.1 MiB)
16:00:48.181 INFO  SparkContext - Created broadcast 1958 from broadcast at MarkDuplicatesSparkUtils.java:126
16:00:48.181 INFO  MemoryStore - Block broadcast_1959 stored as values in memory (estimated size 136.0 B, free 1908.4 MiB)
16:00:48.181 INFO  MemoryStore - Block broadcast_1959_piece0 stored as bytes in memory (estimated size 21.0 B, free 1908.4 MiB)
16:00:48.181 INFO  BlockManagerInfo - Added broadcast_1959_piece0 in memory on localhost:41411 (size: 21.0 B, free: 1918.1 MiB)
16:00:48.181 INFO  SparkContext - Created broadcast 1959 from broadcast at MarkDuplicatesSparkUtils.java:127
16:00:48.192 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
16:00:48.192 INFO  DAGScheduler - Registering RDD 5416 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 305
16:00:48.193 INFO  DAGScheduler - Registering RDD 5420 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 304
16:00:48.193 INFO  DAGScheduler - Registering RDD 5424 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 303
16:00:48.193 INFO  DAGScheduler - Got job 553 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
16:00:48.193 INFO  DAGScheduler - Final stage: ResultStage 1222 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
16:00:48.193 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1221)
16:00:48.193 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1221)
16:00:48.193 INFO  DAGScheduler - Submitting ShuffleMapStage 1219 (MapPartitionsRDD[5416] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
16:00:48.193 INFO  MemoryStore - Block broadcast_1960 stored as values in memory (estimated size 21.1 KiB, free 1908.4 MiB)
16:00:48.194 INFO  MemoryStore - Block broadcast_1960_piece0 stored as bytes in memory (estimated size 10.9 KiB, free 1908.4 MiB)
16:00:48.194 INFO  BlockManagerInfo - Added broadcast_1960_piece0 in memory on localhost:41411 (size: 10.9 KiB, free: 1918.1 MiB)
16:00:48.194 INFO  SparkContext - Created broadcast 1960 from broadcast at DAGScheduler.scala:1580
16:00:48.194 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))
16:00:48.194 INFO  TaskSchedulerImpl - Adding task set 1219.0 with 1 tasks resource profile 0
16:00:48.195 INFO  TaskSetManager - Starting task 0.0 in stage 1219.0 (TID 1046) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
16:00:48.195 INFO  Executor - Running task 0.0 in stage 1219.0 (TID 1046)
16:00:48.196 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
16:00:48.196 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.198 INFO  Executor - Finished task 0.0 in stage 1219.0 (TID 1046). 1922 bytes result sent to driver
16:00:48.199 INFO  TaskSetManager - Finished task 0.0 in stage 1219.0 (TID 1046) in 5 ms on localhost (executor driver) (1/1)
16:00:48.199 INFO  TaskSchedulerImpl - Removed TaskSet 1219.0, whose tasks have all completed, from pool 
16:00:48.199 INFO  DAGScheduler - ShuffleMapStage 1219 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.006 s
16:00:48.199 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.199 INFO  DAGScheduler - running: HashSet()
16:00:48.199 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1220, ShuffleMapStage 1221, ResultStage 1222)
16:00:48.199 INFO  DAGScheduler - failed: HashSet()
16:00:48.199 INFO  DAGScheduler - Submitting ShuffleMapStage 1220 (MapPartitionsRDD[5420] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
16:00:48.199 INFO  MemoryStore - Block broadcast_1961 stored as values in memory (estimated size 25.2 KiB, free 1908.3 MiB)
16:00:48.200 INFO  MemoryStore - Block broadcast_1961_piece0 stored as bytes in memory (estimated size 13.1 KiB, free 1908.3 MiB)
16:00:48.200 INFO  BlockManagerInfo - Added broadcast_1961_piece0 in memory on localhost:41411 (size: 13.1 KiB, free: 1918.1 MiB)
16:00:48.200 INFO  SparkContext - Created broadcast 1961 from broadcast at DAGScheduler.scala:1580
16:00:48.200 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))
16:00:48.200 INFO  TaskSchedulerImpl - Adding task set 1220.0 with 1 tasks resource profile 0
16:00:48.201 INFO  TaskSetManager - Starting task 0.0 in stage 1220.0 (TID 1047) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
16:00:48.201 INFO  Executor - Running task 0.0 in stage 1220.0 (TID 1047)
16:00:48.202 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
16:00:48.202 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.205 INFO  Executor - Finished task 0.0 in stage 1220.0 (TID 1047). 1879 bytes result sent to driver
16:00:48.205 INFO  TaskSetManager - Finished task 0.0 in stage 1220.0 (TID 1047) in 5 ms on localhost (executor driver) (1/1)
16:00:48.205 INFO  TaskSchedulerImpl - Removed TaskSet 1220.0, whose tasks have all completed, from pool 
16:00:48.205 INFO  DAGScheduler - ShuffleMapStage 1220 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.006 s
16:00:48.205 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.205 INFO  DAGScheduler - running: HashSet()
16:00:48.205 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1221, ResultStage 1222)
16:00:48.205 INFO  DAGScheduler - failed: HashSet()
16:00:48.205 INFO  DAGScheduler - Submitting ShuffleMapStage 1221 (MapPartitionsRDD[5424] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
16:00:48.206 INFO  MemoryStore - Block broadcast_1962 stored as values in memory (estimated size 15.9 KiB, free 1908.3 MiB)
16:00:48.206 INFO  MemoryStore - Block broadcast_1962_piece0 stored as bytes in memory (estimated size 8.3 KiB, free 1908.3 MiB)
16:00:48.206 INFO  BlockManagerInfo - Added broadcast_1962_piece0 in memory on localhost:41411 (size: 8.3 KiB, free: 1918.1 MiB)
16:00:48.207 INFO  SparkContext - Created broadcast 1962 from broadcast at DAGScheduler.scala:1580
16:00:48.207 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))
16:00:48.207 INFO  TaskSchedulerImpl - Adding task set 1221.0 with 1 tasks resource profile 0
16:00:48.207 INFO  TaskSetManager - Starting task 0.0 in stage 1221.0 (TID 1048) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:48.208 INFO  Executor - Running task 0.0 in stage 1221.0 (TID 1048)
16:00:48.209 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
16:00:48.209 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.210 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
16:00:48.210 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.211 INFO  Executor - Finished task 0.0 in stage 1221.0 (TID 1048). 1879 bytes result sent to driver
16:00:48.212 INFO  TaskSetManager - Finished task 0.0 in stage 1221.0 (TID 1048) in 5 ms on localhost (executor driver) (1/1)
16:00:48.212 INFO  TaskSchedulerImpl - Removed TaskSet 1221.0, whose tasks have all completed, from pool 
16:00:48.212 INFO  DAGScheduler - ShuffleMapStage 1221 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.007 s
16:00:48.212 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.212 INFO  DAGScheduler - running: HashSet()
16:00:48.212 INFO  DAGScheduler - waiting: HashSet(ResultStage 1222)
16:00:48.212 INFO  DAGScheduler - failed: HashSet()
16:00:48.212 INFO  DAGScheduler - Submitting ResultStage 1222 (MapPartitionsRDD[5426] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
16:00:48.213 INFO  MemoryStore - Block broadcast_1963 stored as values in memory (estimated size 17.1 KiB, free 1908.3 MiB)
16:00:48.213 INFO  MemoryStore - Block broadcast_1963_piece0 stored as bytes in memory (estimated size 9.0 KiB, free 1908.3 MiB)
16:00:48.213 INFO  BlockManagerInfo - Added broadcast_1963_piece0 in memory on localhost:41411 (size: 9.0 KiB, free: 1918.1 MiB)
16:00:48.213 INFO  SparkContext - Created broadcast 1963 from broadcast at DAGScheduler.scala:1580
16:00:48.213 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))
16:00:48.213 INFO  TaskSchedulerImpl - Adding task set 1222.0 with 1 tasks resource profile 0
16:00:48.214 INFO  TaskSetManager - Starting task 0.0 in stage 1222.0 (TID 1049) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:48.214 INFO  Executor - Running task 0.0 in stage 1222.0 (TID 1049)
16:00:48.215 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
16:00:48.215 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.216 INFO  Executor - Finished task 0.0 in stage 1222.0 (TID 1049). 1887 bytes result sent to driver
16:00:48.216 INFO  TaskSetManager - Finished task 0.0 in stage 1222.0 (TID 1049) in 2 ms on localhost (executor driver) (1/1)
16:00:48.216 INFO  TaskSchedulerImpl - Removed TaskSet 1222.0, whose tasks have all completed, from pool 
16:00:48.216 INFO  DAGScheduler - ResultStage 1222 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.004 s
16:00:48.216 INFO  DAGScheduler - Job 553 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:48.216 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1222: Stage finished
16:00:48.217 INFO  DAGScheduler - Job 553 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.024362 s
16:00:48.226 INFO  MemoryStore - Block broadcast_1964 stored as values in memory (estimated size 5.6 KiB, free 1908.3 MiB)
16:00:48.226 INFO  MemoryStore - Block broadcast_1964_piece0 stored as bytes in memory (estimated size 500.0 B, free 1908.3 MiB)
16:00:48.226 INFO  BlockManagerInfo - Added broadcast_1964_piece0 in memory on localhost:41411 (size: 500.0 B, free: 1918.1 MiB)
16:00:48.227 INFO  SparkContext - Created broadcast 1964 from broadcast at ReadsSparkSink.java:133
16:00:48.230 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
16:00:48.230 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:48.230 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:48.241 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
16:00:48.242 INFO  DAGScheduler - Registering RDD 5428 (mapToPair at SparkUtils.java:161) as input to shuffle 306
16:00:48.242 INFO  DAGScheduler - Got job 554 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
16:00:48.242 INFO  DAGScheduler - Final stage: ResultStage 1227 (runJob at SparkHadoopWriter.scala:83)
16:00:48.242 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1226)
16:00:48.242 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1226)
16:00:48.242 INFO  DAGScheduler - Submitting ShuffleMapStage 1226 (MapPartitionsRDD[5428] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:48.243 INFO  MemoryStore - Block broadcast_1965 stored as values in memory (estimated size 15.0 KiB, free 1908.2 MiB)
16:00:48.243 INFO  MemoryStore - Block broadcast_1965_piece0 stored as bytes in memory (estimated size 7.8 KiB, free 1908.2 MiB)
16:00:48.243 INFO  BlockManagerInfo - Added broadcast_1965_piece0 in memory on localhost:41411 (size: 7.8 KiB, free: 1918.1 MiB)
16:00:48.243 INFO  SparkContext - Created broadcast 1965 from broadcast at DAGScheduler.scala:1580
16:00:48.243 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))
16:00:48.243 INFO  TaskSchedulerImpl - Adding task set 1226.0 with 1 tasks resource profile 0
16:00:48.244 INFO  TaskSetManager - Starting task 0.0 in stage 1226.0 (TID 1050) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:48.244 INFO  Executor - Running task 0.0 in stage 1226.0 (TID 1050)
16:00:48.245 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
16:00:48.245 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.247 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
16:00:48.247 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.248 INFO  Executor - Finished task 0.0 in stage 1226.0 (TID 1050). 1879 bytes result sent to driver
16:00:48.248 INFO  TaskSetManager - Finished task 0.0 in stage 1226.0 (TID 1050) in 4 ms on localhost (executor driver) (1/1)
16:00:48.248 INFO  TaskSchedulerImpl - Removed TaskSet 1226.0, whose tasks have all completed, from pool 
16:00:48.248 INFO  DAGScheduler - ShuffleMapStage 1226 (mapToPair at SparkUtils.java:161) finished in 0.006 s
16:00:48.248 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.248 INFO  DAGScheduler - running: HashSet()
16:00:48.248 INFO  DAGScheduler - waiting: HashSet(ResultStage 1227)
16:00:48.248 INFO  DAGScheduler - failed: HashSet()
16:00:48.248 INFO  DAGScheduler - Submitting ResultStage 1227 (MapPartitionsRDD[5434] at saveAsTextFile at SamSink.java:65), which has no missing parents
16:00:48.255 INFO  MemoryStore - Block broadcast_1966 stored as values in memory (estimated size 159.8 KiB, free 1908.1 MiB)
16:00:48.256 INFO  MemoryStore - Block broadcast_1966_piece0 stored as bytes in memory (estimated size 71.6 KiB, free 1908.0 MiB)
16:00:48.256 INFO  BlockManagerInfo - Added broadcast_1966_piece0 in memory on localhost:41411 (size: 71.6 KiB, free: 1918.0 MiB)
16:00:48.256 INFO  SparkContext - Created broadcast 1966 from broadcast at DAGScheduler.scala:1580
16:00:48.256 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))
16:00:48.256 INFO  TaskSchedulerImpl - Adding task set 1227.0 with 1 tasks resource profile 0
16:00:48.256 INFO  TaskSetManager - Starting task 0.0 in stage 1227.0 (TID 1051) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:48.257 INFO  Executor - Running task 0.0 in stage 1227.0 (TID 1051)
16:00:48.260 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
16:00:48.260 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.261 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
16:00:48.262 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:48.262 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:48.268 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271600484426026107890261319_5434_m_000000_0' to file:/tmp/MarkDups5873944721662252996/MarkDups.sam.parts/_temporary/0/task_202505271600484426026107890261319_5434_m_000000
16:00:48.268 INFO  SparkHadoopMapRedUtil - attempt_202505271600484426026107890261319_5434_m_000000_0: Committed. Elapsed time: 0 ms.
16:00:48.268 INFO  Executor - Finished task 0.0 in stage 1227.0 (TID 1051). 1858 bytes result sent to driver
16:00:48.268 INFO  TaskSetManager - Finished task 0.0 in stage 1227.0 (TID 1051) in 12 ms on localhost (executor driver) (1/1)
16:00:48.268 INFO  TaskSchedulerImpl - Removed TaskSet 1227.0, whose tasks have all completed, from pool 
16:00:48.269 INFO  DAGScheduler - ResultStage 1227 (runJob at SparkHadoopWriter.scala:83) finished in 0.020 s
16:00:48.269 INFO  DAGScheduler - Job 554 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:48.269 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1227: Stage finished
16:00:48.269 INFO  DAGScheduler - Job 554 finished: runJob at SparkHadoopWriter.scala:83, took 0.027401 s
16:00:48.269 INFO  SparkHadoopWriter - Start to commit write Job job_202505271600484426026107890261319_5434.
16:00:48.271 INFO  SparkHadoopWriter - Write Job job_202505271600484426026107890261319_5434 committed. Elapsed time: 2 ms.
16:00:48.275 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups5873944721662252996/MarkDups.sam
16:00:48.277 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups5873944721662252996/MarkDups.sam done
16:00:48.278 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 4:00:48 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
16:00:48.293 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:48.293 INFO  MarkDuplicatesSpark - The Genome Analysis Toolkit (GATK) vf5385f1-SNAPSHOT
16:00:48.293 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
16:00:48.293 INFO  MarkDuplicatesSpark - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:00:48.293 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:00:48.293 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 4:00:48 PM GMT
16:00:48.293 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:48.293 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
16:00:48.293 INFO  MarkDuplicatesSpark - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:00:48.293 INFO  MarkDuplicatesSpark - Picard Version: 3.4.0
16:00:48.293 INFO  MarkDuplicatesSpark - Built for Spark Version: 3.5.0
16:00:48.293 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:00:48.293 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:00:48.293 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:00:48.293 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:00:48.293 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
16:00:48.293 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
16:00:48.293 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
16:00:48.293 INFO  MarkDuplicatesSpark - Requester pays: disabled
16:00:48.293 INFO  MarkDuplicatesSpark - Initializing engine
16:00:48.293 INFO  MarkDuplicatesSpark - Done initializing engine
16:00:48.293 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
16:00:48.295 INFO  MemoryStore - Block broadcast_1967 stored as values in memory (estimated size 305.5 KiB, free 1907.7 MiB)
16:00:48.302 INFO  MemoryStore - Block broadcast_1967_piece0 stored as bytes in memory (estimated size 64.1 KiB, free 1907.7 MiB)
16:00:48.302 INFO  BlockManagerInfo - Added broadcast_1967_piece0 in memory on localhost:41411 (size: 64.1 KiB, free: 1918.0 MiB)
16:00:48.302 INFO  SparkContext - Created broadcast 1967 from newAPIHadoopFile at PathSplitSource.java:96
16:00:48.322 INFO  MemoryStore - Block broadcast_1968 stored as values in memory (estimated size 305.5 KiB, free 1907.4 MiB)
16:00:48.328 INFO  MemoryStore - Block broadcast_1968_piece0 stored as bytes in memory (estimated size 64.1 KiB, free 1907.3 MiB)
16:00:48.328 INFO  BlockManagerInfo - Added broadcast_1968_piece0 in memory on localhost:41411 (size: 64.1 KiB, free: 1917.9 MiB)
16:00:48.329 INFO  SparkContext - Created broadcast 1968 from newAPIHadoopFile at PathSplitSource.java:96
16:00:48.360 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
16:00:48.361 INFO  FileInputFormat - Total input files to process : 1
16:00:48.361 INFO  DAGScheduler - Registering RDD 5448 (mapToPair at SparkUtils.java:161) as input to shuffle 307
16:00:48.361 INFO  DAGScheduler - Got job 555 (collect at SparkUtils.java:205) with 1 output partitions
16:00:48.361 INFO  DAGScheduler - Final stage: ResultStage 1229 (collect at SparkUtils.java:205)
16:00:48.361 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1228)
16:00:48.361 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1228)
16:00:48.361 INFO  DAGScheduler - Submitting ShuffleMapStage 1228 (MapPartitionsRDD[5448] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:48.376 INFO  BlockManagerInfo - Removed broadcast_1958_piece0 on localhost:41411 in memory (size: 24.0 B, free: 1917.9 MiB)
16:00:48.376 INFO  BlockManagerInfo - Removed broadcast_1954_piece0 on localhost:41411 in memory (size: 64.0 KiB, free: 1918.0 MiB)
16:00:48.377 INFO  BlockManagerInfo - Removed broadcast_1961_piece0 on localhost:41411 in memory (size: 13.1 KiB, free: 1918.0 MiB)
16:00:48.377 INFO  BlockManagerInfo - Removed broadcast_1927_piece0 on localhost:41411 in memory (size: 71.6 KiB, free: 1918.0 MiB)
16:00:48.377 INFO  BlockManagerInfo - Removed broadcast_1936_piece0 on localhost:41411 in memory (size: 8.5 KiB, free: 1918.0 MiB)
16:00:48.378 INFO  BlockManagerInfo - Removed broadcast_1946_piece0 on localhost:41411 in memory (size: 209.0 B, free: 1918.0 MiB)
16:00:48.378 INFO  BlockManagerInfo - Removed broadcast_1920_piece0 on localhost:41411 in memory (size: 31.0 B, free: 1918.0 MiB)
16:00:48.378 INFO  BlockManagerInfo - Removed broadcast_1929_piece0 on localhost:41411 in memory (size: 64.0 KiB, free: 1918.1 MiB)
16:00:48.379 INFO  BlockManagerInfo - Removed broadcast_1964_piece0 on localhost:41411 in memory (size: 500.0 B, free: 1918.1 MiB)
16:00:48.379 INFO  BlockManagerInfo - Removed broadcast_1959_piece0 on localhost:41411 in memory (size: 21.0 B, free: 1918.1 MiB)
16:00:48.379 INFO  BlockManagerInfo - Removed broadcast_1955_piece0 on localhost:41411 in memory (size: 64.0 KiB, free: 1918.2 MiB)
16:00:48.380 INFO  BlockManagerInfo - Removed broadcast_1938_piece0 on localhost:41411 in memory (size: 663.0 B, free: 1918.2 MiB)
16:00:48.380 INFO  BlockManagerInfo - Removed broadcast_1944_piece0 on localhost:41411 in memory (size: 4.1 KiB, free: 1918.2 MiB)
16:00:48.381 INFO  BlockManagerInfo - Removed broadcast_1945_piece0 on localhost:41411 in memory (size: 540.0 B, free: 1918.2 MiB)
16:00:48.381 INFO  BlockManagerInfo - Removed broadcast_1935_piece0 on localhost:41411 in memory (size: 13.2 KiB, free: 1918.2 MiB)
16:00:48.381 INFO  BlockManagerInfo - Removed broadcast_1966_piece0 on localhost:41411 in memory (size: 71.6 KiB, free: 1918.3 MiB)
16:00:48.382 INFO  BlockManagerInfo - Removed broadcast_1916_piece0 on localhost:41411 in memory (size: 64.0 KiB, free: 1918.3 MiB)
16:00:48.382 INFO  BlockManagerInfo - Removed broadcast_1942_piece0 on localhost:41411 in memory (size: 64.0 KiB, free: 1918.4 MiB)
16:00:48.382 INFO  BlockManagerInfo - Removed broadcast_1950_piece0 on localhost:41411 in memory (size: 18.0 KiB, free: 1918.4 MiB)
16:00:48.383 INFO  BlockManagerInfo - Removed broadcast_1930_piece0 on localhost:41411 in memory (size: 200.3 KiB, free: 1918.6 MiB)
16:00:48.383 INFO  BlockManagerInfo - Removed broadcast_1967_piece0 on localhost:41411 in memory (size: 64.1 KiB, free: 1918.7 MiB)
16:00:48.383 INFO  BlockManagerInfo - Removed broadcast_1956_piece0 on localhost:41411 in memory (size: 200.0 KiB, free: 1918.9 MiB)
16:00:48.384 INFO  BlockManagerInfo - Removed broadcast_1937_piece0 on localhost:41411 in memory (size: 9.1 KiB, free: 1918.9 MiB)
16:00:48.384 INFO  BlockManagerInfo - Removed broadcast_1925_piece0 on localhost:41411 in memory (size: 663.0 B, free: 1918.9 MiB)
16:00:48.384 INFO  BlockManagerInfo - Removed broadcast_1952_piece0 on localhost:41411 in memory (size: 16.8 KiB, free: 1918.9 MiB)
16:00:48.385 INFO  BlockManagerInfo - Removed broadcast_1949_piece0 on localhost:41411 in memory (size: 17.3 KiB, free: 1918.9 MiB)
16:00:48.385 INFO  BlockManagerInfo - Removed broadcast_1965_piece0 on localhost:41411 in memory (size: 7.8 KiB, free: 1918.9 MiB)
16:00:48.386 INFO  BlockManagerInfo - Removed broadcast_1943_piece0 on localhost:41411 in memory (size: 208.9 KiB, free: 1919.1 MiB)
16:00:48.387 INFO  BlockManagerInfo - Removed broadcast_1941_piece0 on localhost:41411 in memory (size: 64.0 KiB, free: 1919.2 MiB)
16:00:48.387 INFO  BlockManagerInfo - Removed broadcast_1947_piece0 on localhost:41411 in memory (size: 19.8 KiB, free: 1919.2 MiB)
16:00:48.387 INFO  BlockManagerInfo - Removed broadcast_1934_piece0 on localhost:41411 in memory (size: 11.2 KiB, free: 1919.2 MiB)
16:00:48.388 INFO  BlockManagerInfo - Removed broadcast_1940_piece0 on localhost:41411 in memory (size: 71.6 KiB, free: 1919.3 MiB)
16:00:48.388 INFO  BlockManagerInfo - Removed broadcast_1957_piece0 on localhost:41411 in memory (size: 4.1 KiB, free: 1919.3 MiB)
16:00:48.389 INFO  MemoryStore - Block broadcast_1969 stored as values in memory (estimated size 480.2 KiB, free 1912.5 MiB)
16:00:48.389 INFO  BlockManagerInfo - Removed broadcast_1948_piece0 on localhost:41411 in memory (size: 22.0 KiB, free: 1919.3 MiB)
16:00:48.390 INFO  BlockManagerInfo - Removed broadcast_1960_piece0 on localhost:41411 in memory (size: 10.9 KiB, free: 1919.3 MiB)
16:00:48.390 INFO  BlockManagerInfo - Removed broadcast_1953_piece0 on localhost:41411 in memory (size: 80.5 KiB, free: 1919.4 MiB)
16:00:48.390 INFO  BlockManagerInfo - Removed broadcast_1933_piece0 on localhost:41411 in memory (size: 31.0 B, free: 1919.4 MiB)
16:00:48.391 INFO  BlockManagerInfo - Removed broadcast_1919_piece0 on localhost:41411 in memory (size: 19.0 B, free: 1919.4 MiB)
16:00:48.391 INFO  BlockManagerInfo - Removed broadcast_1963_piece0 on localhost:41411 in memory (size: 9.0 KiB, free: 1919.4 MiB)
16:00:48.391 INFO  MemoryStore - Block broadcast_1969_piece0 stored as bytes in memory (estimated size 206.2 KiB, free 1912.7 MiB)
16:00:48.391 INFO  BlockManagerInfo - Added broadcast_1969_piece0 in memory on localhost:41411 (size: 206.2 KiB, free: 1919.2 MiB)
16:00:48.391 INFO  SparkContext - Created broadcast 1969 from broadcast at DAGScheduler.scala:1580
16:00:48.392 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))
16:00:48.392 INFO  TaskSchedulerImpl - Adding task set 1228.0 with 1 tasks resource profile 0
16:00:48.392 INFO  BlockManagerInfo - Removed broadcast_1951_piece0 on localhost:41411 in memory (size: 7.9 KiB, free: 1919.2 MiB)
16:00:48.392 INFO  BlockManagerInfo - Removed broadcast_1962_piece0 on localhost:41411 in memory (size: 8.3 KiB, free: 1919.2 MiB)
16:00:48.392 INFO  TaskSetManager - Starting task 0.0 in stage 1228.0 (TID 1052) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9673 bytes) 
16:00:48.392 INFO  Executor - Running task 0.0 in stage 1228.0 (TID 1052)
16:00:48.392 INFO  BlockManagerInfo - Removed broadcast_1932_piece0 on localhost:41411 in memory (size: 19.0 B, free: 1919.2 MiB)
16:00:48.393 INFO  BlockManagerInfo - Removed broadcast_1939_piece0 on localhost:41411 in memory (size: 8.0 KiB, free: 1919.2 MiB)
16:00:48.394 INFO  BlockManagerInfo - Removed broadcast_1931_piece0 on localhost:41411 in memory (size: 4.1 KiB, free: 1919.2 MiB)
16:00:48.394 INFO  BlockManagerInfo - Removed broadcast_1928_piece0 on localhost:41411 in memory (size: 64.0 KiB, free: 1919.3 MiB)
16:00:48.427 INFO  NewHadoopRDD - Input split: file:/gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/inputSingleLibrarySolexa16404.bam:0+5416
16:00:48.432 INFO  Executor - Finished task 0.0 in stage 1228.0 (TID 1052). 1148 bytes result sent to driver
16:00:48.432 INFO  TaskSetManager - Finished task 0.0 in stage 1228.0 (TID 1052) in 40 ms on localhost (executor driver) (1/1)
16:00:48.432 INFO  TaskSchedulerImpl - Removed TaskSet 1228.0, whose tasks have all completed, from pool 
16:00:48.433 INFO  DAGScheduler - ShuffleMapStage 1228 (mapToPair at SparkUtils.java:161) finished in 0.072 s
16:00:48.433 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.433 INFO  DAGScheduler - running: HashSet()
16:00:48.433 INFO  DAGScheduler - waiting: HashSet(ResultStage 1229)
16:00:48.433 INFO  DAGScheduler - failed: HashSet()
16:00:48.433 INFO  DAGScheduler - Submitting ResultStage 1229 (MapPartitionsRDD[5451] at mapPartitions at SparkUtils.java:188), which has no missing parents
16:00:48.433 INFO  MemoryStore - Block broadcast_1970 stored as values in memory (estimated size 7.4 KiB, free 1913.3 MiB)
16:00:48.434 INFO  MemoryStore - Block broadcast_1970_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1913.3 MiB)
16:00:48.434 INFO  BlockManagerInfo - Added broadcast_1970_piece0 in memory on localhost:41411 (size: 4.1 KiB, free: 1919.3 MiB)
16:00:48.434 INFO  SparkContext - Created broadcast 1970 from broadcast at DAGScheduler.scala:1580
16:00:48.434 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))
16:00:48.434 INFO  TaskSchedulerImpl - Adding task set 1229.0 with 1 tasks resource profile 0
16:00:48.435 INFO  TaskSetManager - Starting task 0.0 in stage 1229.0 (TID 1053) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:48.435 INFO  Executor - Running task 0.0 in stage 1229.0 (TID 1053)
16:00:48.436 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
16:00:48.436 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.437 INFO  Executor - Finished task 0.0 in stage 1229.0 (TID 1053). 2039 bytes result sent to driver
16:00:48.437 INFO  TaskSetManager - Finished task 0.0 in stage 1229.0 (TID 1053) in 3 ms on localhost (executor driver) (1/1)
16:00:48.437 INFO  TaskSchedulerImpl - Removed TaskSet 1229.0, whose tasks have all completed, from pool 
16:00:48.437 INFO  DAGScheduler - ResultStage 1229 (collect at SparkUtils.java:205) finished in 0.004 s
16:00:48.437 INFO  DAGScheduler - Job 555 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:48.438 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1229: Stage finished
16:00:48.438 INFO  DAGScheduler - Job 555 finished: collect at SparkUtils.java:205, took 0.077484 s
16:00:48.441 INFO  MemoryStore - Block broadcast_1971 stored as values in memory (estimated size 392.0 B, free 1913.3 MiB)
16:00:48.442 INFO  MemoryStore - Block broadcast_1971_piece0 stored as bytes in memory (estimated size 33.0 B, free 1913.3 MiB)
16:00:48.442 INFO  BlockManagerInfo - Added broadcast_1971_piece0 in memory on localhost:41411 (size: 33.0 B, free: 1919.3 MiB)
16:00:48.442 INFO  SparkContext - Created broadcast 1971 from broadcast at MarkDuplicatesSparkUtils.java:126
16:00:48.442 INFO  MemoryStore - Block broadcast_1972 stored as values in memory (estimated size 144.0 B, free 1913.3 MiB)
16:00:48.442 INFO  MemoryStore - Block broadcast_1972_piece0 stored as bytes in memory (estimated size 28.0 B, free 1913.3 MiB)
16:00:48.442 INFO  BlockManagerInfo - Added broadcast_1972_piece0 in memory on localhost:41411 (size: 28.0 B, free: 1919.3 MiB)
16:00:48.443 INFO  SparkContext - Created broadcast 1972 from broadcast at MarkDuplicatesSparkUtils.java:127
16:00:48.455 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
16:00:48.455 INFO  DAGScheduler - Registering RDD 5460 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 310
16:00:48.455 INFO  DAGScheduler - Registering RDD 5464 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 309
16:00:48.455 INFO  DAGScheduler - Registering RDD 5468 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 308
16:00:48.455 INFO  DAGScheduler - Got job 556 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
16:00:48.455 INFO  DAGScheduler - Final stage: ResultStage 1234 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
16:00:48.455 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1233)
16:00:48.455 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1233)
16:00:48.456 INFO  DAGScheduler - Submitting ShuffleMapStage 1231 (MapPartitionsRDD[5460] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
16:00:48.456 INFO  MemoryStore - Block broadcast_1973 stored as values in memory (estimated size 45.2 KiB, free 1913.3 MiB)
16:00:48.457 INFO  MemoryStore - Block broadcast_1973_piece0 stored as bytes in memory (estimated size 17.1 KiB, free 1913.3 MiB)
16:00:48.457 INFO  BlockManagerInfo - Added broadcast_1973_piece0 in memory on localhost:41411 (size: 17.1 KiB, free: 1919.3 MiB)
16:00:48.457 INFO  SparkContext - Created broadcast 1973 from broadcast at DAGScheduler.scala:1580
16:00:48.457 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))
16:00:48.457 INFO  TaskSchedulerImpl - Adding task set 1231.0 with 1 tasks resource profile 0
16:00:48.458 INFO  TaskSetManager - Starting task 0.0 in stage 1231.0 (TID 1054) (localhost, executor driver, partition 0, NODE_LOCAL, 9813 bytes) 
16:00:48.458 INFO  Executor - Running task 0.0 in stage 1231.0 (TID 1054)
16:00:48.459 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
16:00:48.459 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.462 INFO  Executor - Finished task 0.0 in stage 1231.0 (TID 1054). 1922 bytes result sent to driver
16:00:48.462 INFO  TaskSetManager - Finished task 0.0 in stage 1231.0 (TID 1054) in 5 ms on localhost (executor driver) (1/1)
16:00:48.462 INFO  TaskSchedulerImpl - Removed TaskSet 1231.0, whose tasks have all completed, from pool 
16:00:48.462 INFO  DAGScheduler - ShuffleMapStage 1231 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.006 s
16:00:48.462 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.462 INFO  DAGScheduler - running: HashSet()
16:00:48.462 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1232, ShuffleMapStage 1233, ResultStage 1234)
16:00:48.462 INFO  DAGScheduler - failed: HashSet()
16:00:48.462 INFO  DAGScheduler - Submitting ShuffleMapStage 1232 (MapPartitionsRDD[5464] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
16:00:48.463 INFO  MemoryStore - Block broadcast_1974 stored as values in memory (estimated size 49.3 KiB, free 1913.2 MiB)
16:00:48.464 INFO  MemoryStore - Block broadcast_1974_piece0 stored as bytes in memory (estimated size 19.3 KiB, free 1913.2 MiB)
16:00:48.464 INFO  BlockManagerInfo - Added broadcast_1974_piece0 in memory on localhost:41411 (size: 19.3 KiB, free: 1919.2 MiB)
16:00:48.464 INFO  SparkContext - Created broadcast 1974 from broadcast at DAGScheduler.scala:1580
16:00:48.464 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))
16:00:48.464 INFO  TaskSchedulerImpl - Adding task set 1232.0 with 1 tasks resource profile 0
16:00:48.464 INFO  TaskSetManager - Starting task 0.0 in stage 1232.0 (TID 1055) (localhost, executor driver, partition 0, NODE_LOCAL, 9288 bytes) 
16:00:48.465 INFO  Executor - Running task 0.0 in stage 1232.0 (TID 1055)
16:00:48.466 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
16:00:48.466 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.469 INFO  Executor - Finished task 0.0 in stage 1232.0 (TID 1055). 1922 bytes result sent to driver
16:00:48.469 INFO  TaskSetManager - Finished task 0.0 in stage 1232.0 (TID 1055) in 5 ms on localhost (executor driver) (1/1)
16:00:48.469 INFO  TaskSchedulerImpl - Removed TaskSet 1232.0, whose tasks have all completed, from pool 
16:00:48.470 INFO  DAGScheduler - ShuffleMapStage 1232 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.007 s
16:00:48.470 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.470 INFO  DAGScheduler - running: HashSet()
16:00:48.470 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1233, ResultStage 1234)
16:00:48.470 INFO  DAGScheduler - failed: HashSet()
16:00:48.470 INFO  DAGScheduler - Submitting ShuffleMapStage 1233 (MapPartitionsRDD[5468] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
16:00:48.470 INFO  MemoryStore - Block broadcast_1975 stored as values in memory (estimated size 40.0 KiB, free 1913.1 MiB)
16:00:48.471 INFO  MemoryStore - Block broadcast_1975_piece0 stored as bytes in memory (estimated size 14.5 KiB, free 1913.1 MiB)
16:00:48.471 INFO  BlockManagerInfo - Added broadcast_1975_piece0 in memory on localhost:41411 (size: 14.5 KiB, free: 1919.2 MiB)
16:00:48.471 INFO  SparkContext - Created broadcast 1975 from broadcast at DAGScheduler.scala:1580
16:00:48.471 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))
16:00:48.471 INFO  TaskSchedulerImpl - Adding task set 1233.0 with 1 tasks resource profile 0
16:00:48.472 INFO  TaskSetManager - Starting task 0.0 in stage 1233.0 (TID 1056) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:48.472 INFO  Executor - Running task 0.0 in stage 1233.0 (TID 1056)
16:00:48.473 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
16:00:48.473 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.474 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
16:00:48.474 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.475 INFO  Executor - Finished task 0.0 in stage 1233.0 (TID 1056). 1879 bytes result sent to driver
16:00:48.476 INFO  TaskSetManager - Finished task 0.0 in stage 1233.0 (TID 1056) in 4 ms on localhost (executor driver) (1/1)
16:00:48.476 INFO  TaskSchedulerImpl - Removed TaskSet 1233.0, whose tasks have all completed, from pool 
16:00:48.476 INFO  DAGScheduler - ShuffleMapStage 1233 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.006 s
16:00:48.476 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.476 INFO  DAGScheduler - running: HashSet()
16:00:48.476 INFO  DAGScheduler - waiting: HashSet(ResultStage 1234)
16:00:48.476 INFO  DAGScheduler - failed: HashSet()
16:00:48.476 INFO  DAGScheduler - Submitting ResultStage 1234 (MapPartitionsRDD[5470] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
16:00:48.476 INFO  MemoryStore - Block broadcast_1976 stored as values in memory (estimated size 41.2 KiB, free 1913.1 MiB)
16:00:48.477 INFO  MemoryStore - Block broadcast_1976_piece0 stored as bytes in memory (estimated size 15.3 KiB, free 1913.1 MiB)
16:00:48.477 INFO  BlockManagerInfo - Added broadcast_1976_piece0 in memory on localhost:41411 (size: 15.3 KiB, free: 1919.2 MiB)
16:00:48.477 INFO  SparkContext - Created broadcast 1976 from broadcast at DAGScheduler.scala:1580
16:00:48.477 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))
16:00:48.477 INFO  TaskSchedulerImpl - Adding task set 1234.0 with 1 tasks resource profile 0
16:00:48.477 INFO  TaskSetManager - Starting task 0.0 in stage 1234.0 (TID 1057) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:48.478 INFO  Executor - Running task 0.0 in stage 1234.0 (TID 1057)
16:00:48.479 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
16:00:48.479 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.480 INFO  Executor - Finished task 0.0 in stage 1234.0 (TID 1057). 1944 bytes result sent to driver
16:00:48.480 INFO  TaskSetManager - Finished task 0.0 in stage 1234.0 (TID 1057) in 3 ms on localhost (executor driver) (1/1)
16:00:48.481 INFO  TaskSchedulerImpl - Removed TaskSet 1234.0, whose tasks have all completed, from pool 
16:00:48.481 INFO  DAGScheduler - ResultStage 1234 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.005 s
16:00:48.481 INFO  DAGScheduler - Job 556 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:48.481 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1234: Stage finished
16:00:48.481 INFO  DAGScheduler - Job 556 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.026015 s
16:00:48.491 INFO  MemoryStore - Block broadcast_1977 stored as values in memory (estimated size 93.5 KiB, free 1913.0 MiB)
16:00:48.491 INFO  MemoryStore - Block broadcast_1977_piece0 stored as bytes in memory (estimated size 5.6 KiB, free 1913.0 MiB)
16:00:48.491 INFO  BlockManagerInfo - Added broadcast_1977_piece0 in memory on localhost:41411 (size: 5.6 KiB, free: 1919.2 MiB)
16:00:48.492 INFO  SparkContext - Created broadcast 1977 from broadcast at ReadsSparkSink.java:133
16:00:48.495 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
16:00:48.495 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:48.495 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:48.506 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
16:00:48.506 INFO  DAGScheduler - Registering RDD 5472 (mapToPair at SparkUtils.java:161) as input to shuffle 311
16:00:48.506 INFO  DAGScheduler - Got job 557 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
16:00:48.506 INFO  DAGScheduler - Final stage: ResultStage 1239 (runJob at SparkHadoopWriter.scala:83)
16:00:48.506 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1238)
16:00:48.507 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1238)
16:00:48.507 INFO  DAGScheduler - Submitting ShuffleMapStage 1238 (MapPartitionsRDD[5472] at mapToPair at SparkUtils.java:161), which has no missing parents
16:00:48.507 INFO  MemoryStore - Block broadcast_1978 stored as values in memory (estimated size 39.1 KiB, free 1912.9 MiB)
16:00:48.508 INFO  MemoryStore - Block broadcast_1978_piece0 stored as bytes in memory (estimated size 14.1 KiB, free 1912.9 MiB)
16:00:48.508 INFO  BlockManagerInfo - Added broadcast_1978_piece0 in memory on localhost:41411 (size: 14.1 KiB, free: 1919.2 MiB)
16:00:48.508 INFO  SparkContext - Created broadcast 1978 from broadcast at DAGScheduler.scala:1580
16:00:48.508 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))
16:00:48.508 INFO  TaskSchedulerImpl - Adding task set 1238.0 with 1 tasks resource profile 0
16:00:48.509 INFO  TaskSetManager - Starting task 0.0 in stage 1238.0 (TID 1058) (localhost, executor driver, partition 0, NODE_LOCAL, 9871 bytes) 
16:00:48.509 INFO  Executor - Running task 0.0 in stage 1238.0 (TID 1058)
16:00:48.510 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
16:00:48.510 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.512 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
16:00:48.512 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.513 INFO  Executor - Finished task 0.0 in stage 1238.0 (TID 1058). 1879 bytes result sent to driver
16:00:48.513 INFO  TaskSetManager - Finished task 0.0 in stage 1238.0 (TID 1058) in 5 ms on localhost (executor driver) (1/1)
16:00:48.513 INFO  TaskSchedulerImpl - Removed TaskSet 1238.0, whose tasks have all completed, from pool 
16:00:48.513 INFO  DAGScheduler - ShuffleMapStage 1238 (mapToPair at SparkUtils.java:161) finished in 0.006 s
16:00:48.513 INFO  DAGScheduler - looking for newly runnable stages
16:00:48.513 INFO  DAGScheduler - running: HashSet()
16:00:48.513 INFO  DAGScheduler - waiting: HashSet(ResultStage 1239)
16:00:48.513 INFO  DAGScheduler - failed: HashSet()
16:00:48.514 INFO  DAGScheduler - Submitting ResultStage 1239 (MapPartitionsRDD[5478] at saveAsTextFile at SamSink.java:65), which has no missing parents
16:00:48.520 INFO  MemoryStore - Block broadcast_1979 stored as values in memory (estimated size 183.9 KiB, free 1912.7 MiB)
16:00:48.521 INFO  MemoryStore - Block broadcast_1979_piece0 stored as bytes in memory (estimated size 77.8 KiB, free 1912.7 MiB)
16:00:48.521 INFO  BlockManagerInfo - Added broadcast_1979_piece0 in memory on localhost:41411 (size: 77.8 KiB, free: 1919.1 MiB)
16:00:48.521 INFO  SparkContext - Created broadcast 1979 from broadcast at DAGScheduler.scala:1580
16:00:48.521 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))
16:00:48.521 INFO  TaskSchedulerImpl - Adding task set 1239.0 with 1 tasks resource profile 0
16:00:48.521 INFO  TaskSetManager - Starting task 0.0 in stage 1239.0 (TID 1059) (localhost, executor driver, partition 0, NODE_LOCAL, 9299 bytes) 
16:00:48.521 INFO  Executor - Running task 0.0 in stage 1239.0 (TID 1059)
16:00:48.525 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
16:00:48.525 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
16:00:48.526 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
16:00:48.526 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
16:00:48.526 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
16:00:48.532 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271600486849917418429370855_5478_m_000000_0' to file:/tmp/MarkDups6971703233217782012/MarkDups.sam.parts/_temporary/0/task_202505271600486849917418429370855_5478_m_000000
16:00:48.532 INFO  SparkHadoopMapRedUtil - attempt_202505271600486849917418429370855_5478_m_000000_0: Committed. Elapsed time: 0 ms.
16:00:48.532 INFO  Executor - Finished task 0.0 in stage 1239.0 (TID 1059). 1858 bytes result sent to driver
16:00:48.532 INFO  TaskSetManager - Finished task 0.0 in stage 1239.0 (TID 1059) in 11 ms on localhost (executor driver) (1/1)
16:00:48.532 INFO  TaskSchedulerImpl - Removed TaskSet 1239.0, whose tasks have all completed, from pool 
16:00:48.533 INFO  DAGScheduler - ResultStage 1239 (runJob at SparkHadoopWriter.scala:83) finished in 0.019 s
16:00:48.533 INFO  DAGScheduler - Job 557 is finished. Cancelling potential speculative or zombie tasks for this job
16:00:48.533 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1239: Stage finished
16:00:48.533 INFO  DAGScheduler - Job 557 finished: runJob at SparkHadoopWriter.scala:83, took 0.026670 s
16:00:48.533 INFO  SparkHadoopWriter - Start to commit write Job job_202505271600486849917418429370855_5478.
16:00:48.535 INFO  SparkHadoopWriter - Write Job job_202505271600486849917418429370855_5478 committed. Elapsed time: 2 ms.
16:00:48.539 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups6971703233217782012/MarkDups.sam
16:00:48.541 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups6971703233217782012/MarkDups.sam done
16:00:48.541 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 4:00:48 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:48 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:49 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:49 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:49 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:50 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:50 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:50 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:50 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:51 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:51 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:51 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:52 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:52 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:52 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:53 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:53 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:53 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:54 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
16:00:54.276 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-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.EmptyFragment.<init>(EmptyFragment.java:36) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.MarkDuplicatesSparkRecord.newEmptyFragment(MarkDuplicatesSparkRecord.java:44) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.lambda$transformToDuplicateNames$0(MarkDuplicatesSparkUtils.java:141) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-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-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.api.java.JavaRDDLike.$anonfun$flatMapToPair$1(JavaRDDLike.scala:143) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at scala.collection.Iterator$$anon$10.nextCur(Iterator.scala:594) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:608) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.shuffle.sort.BypassMergeSortShuffleWriter.write(BypassMergeSortShuffleWriter.java:140) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.shuffle.ShuffleWriteProcessor.write(ShuffleWriteProcessor.scala:59) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:104) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:54) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.TaskContext.runTaskWithListeners(TaskContext.scala:161) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.scheduler.Task.run(Task.scala:141) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.executor.Executor$TaskRunner.$anonfun$run$4(Executor.scala:620) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally(SparkErrorUtils.scala:64) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally$(SparkErrorUtils.scala:61) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.util.Utils$.tryWithSafeFinally(Utils.scala:94) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:623) [gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-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) [?:?]
16:00:54.290 ERROR TaskSetManager - Task 0 in stage 1459.0 failed 1 times; aborting job
[May 27, 2025 at 4:00:54 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
16:00:54.529 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-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.EmptyFragment.<init>(EmptyFragment.java:36) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.MarkDuplicatesSparkRecord.newEmptyFragment(MarkDuplicatesSparkRecord.java:44) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.lambda$transformToDuplicateNames$0(MarkDuplicatesSparkUtils.java:141) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-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-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.api.java.JavaRDDLike.$anonfun$flatMapToPair$1(JavaRDDLike.scala:143) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at scala.collection.Iterator$$anon$10.nextCur(Iterator.scala:594) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:608) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.shuffle.sort.BypassMergeSortShuffleWriter.write(BypassMergeSortShuffleWriter.java:140) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.shuffle.ShuffleWriteProcessor.write(ShuffleWriteProcessor.scala:59) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:104) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:54) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.TaskContext.runTaskWithListeners(TaskContext.scala:161) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.scheduler.Task.run(Task.scala:141) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.executor.Executor$TaskRunner.$anonfun$run$4(Executor.scala:620) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally(SparkErrorUtils.scala:64) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally$(SparkErrorUtils.scala:61) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.util.Utils$.tryWithSafeFinally(Utils.scala:94) ~[gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-SNAPSHOT]
	at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:623) [gatk-package-f5385f1-SNAPSHOT-local.jar:f5385f1-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) [?:?]
16:00:54.531 ERROR TaskSetManager - Task 0 in stage 1466.0 failed 1 times; aborting job
[May 27, 2025 at 4:00:54 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:54 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:55 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:55 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:55 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:56 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:56 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:56 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:57 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:57 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:57 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:57 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:58 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:58 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:58 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:59 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:59 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:00:59 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:00 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:00 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:00 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:00 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:01 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:01 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:01 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:02 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:02 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:02 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:03 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:03 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:03 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:03 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:04 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:04 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:04 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:05 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:05 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:05 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:06 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:06 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:06 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:06 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:07 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:07 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:07 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:08 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:08 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:08 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:09 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:09 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:09 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:10 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:10 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:10 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:10 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:11 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:11 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:11 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:12 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:12 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:12 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:13 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:13 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:13 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:13 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:14 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:14 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:14 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:15 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:15 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:15 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:16 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:16 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:16 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:16 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:17 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:17 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:17 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:18 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:18 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:18 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352
[May 27, 2025 at 4:01:19 PM GMT] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1784676352