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

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

152

tests

failures

ignored

59.001s

duration

100%

successful

Tests
Standard error

Tests

Test	Duration	Result
assertThatExpectedOutputUpdateToggleIsDisabled	0s	passed
testAssertAssumeUnsortedFilesAreQueryGroupedFiles	0.565s	passed
testAssertCorrectSortOrderMultipleBams	0.126s	passed
testAssertCorrectSortOrderMultipleBamsOverriding	0.489s	passed
testBulkFragmentsNoDuplicates	0.922s	passed
testBulkFragmentsWithDuplicates	2.006s	passed
testDifferentChromosomesInOppositeOrder	0.300s	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.272s	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.244s	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.255s	passed
testFlowModeFlag	1.521s	passed
testHashCollisionHandling	1.122s	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.306s	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.284s	passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[0](true, true, true)	0.296s	passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[1](true, false, true)	0.310s	passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[2](false, true, true)	0.292s	passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[3](true, true, false)	0.320s	passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[4](true, false, false)	0.302s	passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[5](false, true, false)	0.316s	passed
testMappedFragmentAndMappedPairFirstOfPairNonPrimary	0.291s	passed
testMappedFragmentAndMatePairFirstUnmapped	0.286s	passed
testMappedFragmentAndMatePairSecondUnmapped	0.309s	passed
testMappedPairAndMappedFragmentAndMatePairFirstUnmapped	0.295s	passed
testMappedPairAndMappedFragmentAndMatePairSecondUnmapped	0.319s	passed
testMappedPairAndMatePairFirstOppositeStrandSecondUnmapped	0.297s	passed
testMappedPairAndMatePairFirstUnmapped	0.291s	passed
testMappedPairAndMatePairSecondUnmapped	0.288s	passed
testMappedPairWithFirstEndSamePositionAndOther	0.288s	passed
testMappedPairWithSamePosition	0.298s	passed
testMappedPairWithSamePositionSameCigar	0.284s	passed
testMarkDuplicatesSparkDeletingDuplicateReads[0]([Ljava.io.File;@2c110d0b, 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.344s	passed
testMarkDuplicatesSparkDeletingDuplicateReads[1]([Ljava.io.File;@1277d0d8, 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.373s	passed
testMarkDuplicatesSparkDeletingDuplicateReads[2]([Ljava.io.File;@4ffcf36e, 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
testMarkDuplicatesSparkDeletingDuplicateReads[3]([Ljava.io.File;@429f5e88, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.333s	passed
testMarkDuplicatesSparkDeletingDuplicateReads[4]([Ljava.io.File;@c59d771, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.326s	passed
testMarkDuplicatesSparkDeletingDuplicateReads[5]([Ljava.io.File;@10ef7213, 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.183s	passed
testMarkDuplicatesSparkDeletingDuplicateReads[6]([Ljava.io.File;@2c6b003d, 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.143s	passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[0]([Ljava.io.File;@6021d765, 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.362s	passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[1]([Ljava.io.File;@d2d7aa7, 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.375s	passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[2]([Ljava.io.File;@1305369c, 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.373s	passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[3]([Ljava.io.File;@444ab619, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.338s	passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[4]([Ljava.io.File;@4f097ca4, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.319s	passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[5]([Ljava.io.File;@7e8f7df0, 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.189s	passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[6]([Ljava.io.File;@1365df56, 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.210s	passed
testMarkDuplicatesSparkIntegrationTestLocal[0]([Ljava.io.File;@77fd8e29, 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.339s	passed
testMarkDuplicatesSparkIntegrationTestLocal[1]([Ljava.io.File;@1c000d69, 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;@3770e16, 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.346s	passed
testMarkDuplicatesSparkIntegrationTestLocal[3]([Ljava.io.File;@438338f9, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.344s	passed
testMarkDuplicatesSparkIntegrationTestLocal[4]([Ljava.io.File;@66ae9f0f, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.336s	passed
testMarkDuplicatesSparkIntegrationTestLocal[5]([Ljava.io.File;@2875f192, 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.160s	passed
testMarkDuplicatesSparkIntegrationTestLocal[6]([Ljava.io.File;@1c943, 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.213s	passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[0]([Ljava.io.File;@667cb4c6, 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.332s	passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[1]([Ljava.io.File;@2cd9df4b, 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.347s	passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[2]([Ljava.io.File;@72d8c212, 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.350s	passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[3]([Ljava.io.File;@a231301, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.321s	passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[4]([Ljava.io.File;@719c2c21, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.334s	passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[5]([Ljava.io.File;@20bc1934, 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;@6017f9cb, 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.161s	passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[0]([Ljava.io.File;@10d15162, 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.356s	passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[1]([Ljava.io.File;@7bf5397b, 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.347s	passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[2]([Ljava.io.File;@6652ff8f, 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.365s	passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[3]([Ljava.io.File;@5513fe8, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.323s	passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[4]([Ljava.io.File;@555be95, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]})	0.309s	passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[5]([Ljava.io.File;@61d187f7, 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
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[6]([Ljava.io.File;@48c5e53c, 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
testMatePairFirstUnmapped	0.283s	passed
testMatePairSecondUnmapped	0.292s	passed
testNoReadGroupInRead	0.226s	passed
testNonExistantReadGroupInRead	0.213s	passed
testNullOpticalDuplicates	0.309s	passed
testOpticalDuplicateClusterOneEndSamePositionOneCluster	0.325s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicatesWithinPixelDistance	0.299s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[0](RUNID:7:1203:2886:82292, RUNID:7:1205:3886:16834)	0.310s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[10](RUNID:7:1203:6886:16756, RUNID:7:1203:4886:26756)	0.289s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[11](RUNID:7:1203:2886:34756, RUNID:7:1203:2886:36756)	0.290s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[12](RUNID:7:1203:2886:35756, RUNID:7:1203:2886:36756)	0.299s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[13](RUNID:7:1203:2886:37756, RUNID:7:1203:2886:36756)	0.286s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[14](RUNID:7:1203:2886:38756, RUNID:7:1203:2886:36756)	0.294s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[15](HK3T5CCXX160204:3:1112:11586:37067, HK3T5CCXX160204:3:1112:11586:32144)	0.290s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[1](RUNID:7:1203:2886:16756, RUNID:7:1205:3886:16756)	0.288s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[2](RUNID:7:1204:2886:16756, RUNID:7:1205:3886:16756)	0.293s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[3](RUNID:7:1205:2886:16756, RUNID:7:1205:3886:16756)	0.302s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[4](RUNID:7:1206:2886:16756, RUNID:7:1205:3886:16756)	0.289s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[5](RUNID:7:1207:2886:16756, RUNID:7:1205:3886:16756)	0.291s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[6](RUNID:7:1203:2886:16756, RUNID:7:1203:4886:26756)	0.295s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[7](RUNID:7:1203:3886:16756, RUNID:7:1203:4886:26756)	0.302s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[8](RUNID:7:1203:4886:16756, RUNID:7:1203:4886:26756)	0.293s	passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[9](RUNID:7:1203:5886:16756, RUNID:7:1203:4886:26756)	0.290s	passed
testOpticalDuplicateClusterSamePositionOneOpticalDuplicatesWithinPixelDistance	0.308s	passed
testOpticalDuplicateClustersAddingSecondEndFirstSameCoordinate	0.288s	passed
testOpticalDuplicateFinding	0.287s	passed
testOpticalDuplicateFindingPxelDistance	0.302s	passed
testOpticalDuplicatesAndPCRDuplicatesOrientationDifference	0.297s	passed
testOpticalDuplicatesDifferentReadGroups	0.290s	passed
testOpticalDuplicatesTheSameReadGroup	0.291s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[0](RUNID:7:1203:2886:82292, RUNID:7:1205:3886:16834)	0.292s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[10](RUNID:7:1203:6886:16756, RUNID:7:1203:4886:26756)	0.306s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[11](RUNID:7:1203:2886:34756, RUNID:7:1203:2886:36756)	0.297s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[12](RUNID:7:1203:2886:35756, RUNID:7:1203:2886:36756)	0.332s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[13](RUNID:7:1203:2886:37756, RUNID:7:1203:2886:36756)	0.313s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[14](RUNID:7:1203:2886:38756, RUNID:7:1203:2886:36756)	0.300s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[15](HK3T5CCXX160204:3:1112:11586:37067, HK3T5CCXX160204:3:1112:11586:32144)	0.303s	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.286s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[3](RUNID:7:1205:2886:16756, RUNID:7:1205:3886:16756)	0.285s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[4](RUNID:7:1206:2886:16756, RUNID:7:1205:3886:16756)	0.297s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[5](RUNID:7:1207:2886:16756, RUNID:7:1205:3886:16756)	0.292s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[6](RUNID:7:1203:2886:16756, RUNID:7:1203:4886:26756)	0.295s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[7](RUNID:7:1203:3886:16756, RUNID:7:1203:4886:26756)	0.298s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[8](RUNID:7:1203:4886:16756, RUNID:7:1203:4886:26756)	0.287s	passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[9](RUNID:7:1203:5886:16756, RUNID:7:1203:4886:26756)	0.286s	passed
testPathologicalOrderingAtTheSamePosition	0.290s	passed
testReadSameStartPositionOrientationOverride	0.291s	passed
testReadsHaveSameStartPositionButDifferentChromosomeNonEquivalence	0.287s	passed
testSecondEndIsBeforeFirstInCoordinate	0.302s	passed
testSingleMappedFragment	0.295s	passed
testSingleMappedFragmentAndSingleMappedPair	0.285s	passed
testSingleMappedFragmentAndTwoMappedPairs	0.308s	passed
testSingleMappedPair	0.292s	passed
testSingleUnmappedFragment	0.296s	passed
testSingleUnmappedPair	0.282s	passed
testStackOverFlowPairSetSwap	0.287s	passed
testSupplementaryReadUnmappedMate	0.294s	passed
testThreeGroupsOnDifferentChromosomesOfThreeMappedPairs	0.300s	passed
testThreeMappedPairs	0.289s	passed
testThreeMappedPairsWithMatchingSecondMate	0.285s	passed
testTwoGroupsOnDifferentChromosomesOfThreeMappedPairs	0.285s	passed
testTwoGroupsOnDifferentChromosomesOfTwoFragments	0.284s	passed
testTwoGroupsOnDifferentChromosomesOfTwoMappedPairs	0.314s	passed
testTwoMappedFragments	0.302s	passed
testTwoMappedPairWithSamePosition	0.290s	passed
testTwoMappedPairWithSamePositionDifferentStrands	0.294s	passed
testTwoMappedPairWithSamePositionDifferentStrands2	0.304s	passed
testTwoMappedPairs	0.287s	passed
testTwoMappedPairsAndMappedSecondaryFragment	0.287s	passed
testTwoMappedPairsAndTerminalUnmappedFragment	0.285s	passed
testTwoMappedPairsAndTerminalUnmappedPair	0.297s	passed
testTwoMappedPairsMatesSoftClipped	0.287s	passed
testTwoMappedPairsWithOppositeOrientations	0.291s	passed
testTwoMappedPairsWithOppositeOrientationsNumberTwo	0.296s	passed
testTwoMappedPairsWithSoftClipping	0.288s	passed
testTwoMappedPairsWithSoftClippingBoth	0.303s	passed
testTwoMappedPairsWithSoftClippingFirstOfPairOnly	0.285s	passed
testTwoMappedPairsWithSoftClippingFirstOfPairOnlyNoMateCigar	0.284s	passed
testTwoMappedPairsWithSupplementaryReads[0](true, true, true)	0.288s	passed
testTwoMappedPairsWithSupplementaryReads[1](true, false, true)	0.297s	passed
testTwoMappedPairsWithSupplementaryReads[2](false, true, true)	0.292s	passed
testTwoMappedPairsWithSupplementaryReads[3](true, true, false)	0.293s	passed
testTwoMappedPairsWithSupplementaryReads[4](true, false, false)	0.288s	passed
testTwoMappedPairsWithSupplementaryReads[5](false, true, false)	0.284s	passed
testTwoUnmappedFragments	0.299s	passed

Standard error

[May 27, 2025 at 6:15:09 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:10 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:10 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:11 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:13 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
18:15:13.163 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:13.163 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:15:13.163 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:15:13.163 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:15:13.163 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:15:13.163 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:15:13 PM UTC
18:15:13.163 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:13.163 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:13.164 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:15:13.164 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:15:13.164 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:15:13.164 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:15:13.164 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:15:13.164 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:15:13.164 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:15:13.164 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:15:13.164 INFO  MarkDuplicatesSpark - Initializing engine
18:15:13.164 INFO  MarkDuplicatesSpark - Done initializing engine
18:15:13.164 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:15:13.167 INFO  MemoryStore - Block broadcast_1371 stored as values in memory (estimated size 306.3 KiB, free 1903.7 MiB)
18:15:13.174 INFO  MemoryStore - Block broadcast_1371_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1903.7 MiB)
18:15:13.174 INFO  BlockManagerInfo - Added broadcast_1371_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1919.0 MiB)
18:15:13.174 INFO  SparkContext - Created broadcast 1371 from newAPIHadoopFile at PathSplitSource.java:96
18:15:13.194 INFO  MemoryStore - Block broadcast_1372 stored as values in memory (estimated size 306.3 KiB, free 1903.4 MiB)
18:15:13.201 INFO  MemoryStore - Block broadcast_1372_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1903.3 MiB)
18:15:13.201 INFO  BlockManagerInfo - Added broadcast_1372_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1919.0 MiB)
18:15:13.201 INFO  SparkContext - Created broadcast 1372 from newAPIHadoopFile at PathSplitSource.java:96
18:15:13.234 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:15:13.234 INFO  FileInputFormat - Total input files to process : 1
18:15:13.235 INFO  DAGScheduler - Registering RDD 3483 (mapToPair at SparkUtils.java:161) as input to shuffle 100
18:15:13.235 INFO  DAGScheduler - Got job 423 (collect at SparkUtils.java:205) with 1 output partitions
18:15:13.235 INFO  DAGScheduler - Final stage: ResultStage 735 (collect at SparkUtils.java:205)
18:15:13.236 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 734)
18:15:13.236 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 734)
18:15:13.236 INFO  DAGScheduler - Submitting ShuffleMapStage 734 (MapPartitionsRDD[3483] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:13.253 INFO  MemoryStore - Block broadcast_1373 stored as values in memory (estimated size 460.4 KiB, free 1902.8 MiB)
18:15:13.255 INFO  MemoryStore - Block broadcast_1373_piece0 stored as bytes in memory (estimated size 202.5 KiB, free 1902.6 MiB)
18:15:13.256 INFO  BlockManagerInfo - Added broadcast_1373_piece0 in memory on localhost:44275 (size: 202.5 KiB, free: 1918.8 MiB)
18:15:13.256 INFO  SparkContext - Created broadcast 1373 from broadcast at DAGScheduler.scala:1580
18:15:13.256 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 734 (MapPartitionsRDD[3483] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:13.256 INFO  TaskSchedulerImpl - Adding task set 734.0 with 1 tasks resource profile 0
18:15:13.257 INFO  TaskSetManager - Starting task 0.0 in stage 734.0 (TID 676) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9735 bytes) 
18:15:13.258 INFO  Executor - Running task 0.0 in stage 734.0 (TID 676)
18:15:13.287 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug.bam:0+1507
18:15:13.291 INFO  Executor - Finished task 0.0 in stage 734.0 (TID 676). 1148 bytes result sent to driver
18:15:13.291 INFO  TaskSetManager - Finished task 0.0 in stage 734.0 (TID 676) in 34 ms on localhost (executor driver) (1/1)
18:15:13.292 INFO  TaskSchedulerImpl - Removed TaskSet 734.0, whose tasks have all completed, from pool 
18:15:13.292 INFO  DAGScheduler - ShuffleMapStage 734 (mapToPair at SparkUtils.java:161) finished in 0.056 s
18:15:13.292 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.292 INFO  DAGScheduler - running: HashSet()
18:15:13.292 INFO  DAGScheduler - waiting: HashSet(ResultStage 735)
18:15:13.292 INFO  DAGScheduler - failed: HashSet()
18:15:13.292 INFO  DAGScheduler - Submitting ResultStage 735 (MapPartitionsRDD[3486] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:15:13.293 INFO  MemoryStore - Block broadcast_1374 stored as values in memory (estimated size 7.4 KiB, free 1902.6 MiB)
18:15:13.293 INFO  MemoryStore - Block broadcast_1374_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1902.6 MiB)
18:15:13.293 INFO  BlockManagerInfo - Added broadcast_1374_piece0 in memory on localhost:44275 (size: 4.1 KiB, free: 1918.8 MiB)
18:15:13.294 INFO  SparkContext - Created broadcast 1374 from broadcast at DAGScheduler.scala:1580
18:15:13.294 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 735 (MapPartitionsRDD[3486] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:15:13.294 INFO  TaskSchedulerImpl - Adding task set 735.0 with 1 tasks resource profile 0
18:15:13.294 INFO  TaskSetManager - Starting task 0.0 in stage 735.0 (TID 677) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:13.295 INFO  Executor - Running task 0.0 in stage 735.0 (TID 677)
18:15:13.296 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.296 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.298 INFO  Executor - Finished task 0.0 in stage 735.0 (TID 677). 2238 bytes result sent to driver
18:15:13.298 INFO  TaskSetManager - Finished task 0.0 in stage 735.0 (TID 677) in 4 ms on localhost (executor driver) (1/1)
18:15:13.298 INFO  TaskSchedulerImpl - Removed TaskSet 735.0, whose tasks have all completed, from pool 
18:15:13.298 INFO  DAGScheduler - ResultStage 735 (collect at SparkUtils.java:205) finished in 0.006 s
18:15:13.298 INFO  DAGScheduler - Job 423 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:13.298 INFO  TaskSchedulerImpl - Killing all running tasks in stage 735: Stage finished
18:15:13.299 INFO  DAGScheduler - Job 423 finished: collect at SparkUtils.java:205, took 0.064883 s
18:15:13.303 INFO  MemoryStore - Block broadcast_1375 stored as values in memory (estimated size 1632.0 B, free 1902.6 MiB)
18:15:13.304 INFO  MemoryStore - Block broadcast_1375_piece0 stored as bytes in memory (estimated size 145.0 B, free 1902.6 MiB)
18:15:13.304 INFO  BlockManagerInfo - Added broadcast_1375_piece0 in memory on localhost:44275 (size: 145.0 B, free: 1918.8 MiB)
18:15:13.304 INFO  SparkContext - Created broadcast 1375 from broadcast at MarkDuplicatesSparkUtils.java:126
18:15:13.304 INFO  MemoryStore - Block broadcast_1376 stored as values in memory (estimated size 304.0 B, free 1902.6 MiB)
18:15:13.305 INFO  MemoryStore - Block broadcast_1376_piece0 stored as bytes in memory (estimated size 37.0 B, free 1902.6 MiB)
18:15:13.305 INFO  BlockManagerInfo - Added broadcast_1376_piece0 in memory on localhost:44275 (size: 37.0 B, free: 1918.8 MiB)
18:15:13.305 INFO  SparkContext - Created broadcast 1376 from broadcast at MarkDuplicatesSparkUtils.java:127
18:15:13.317 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:15:13.318 INFO  DAGScheduler - Registering RDD 3495 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 103
18:15:13.318 INFO  DAGScheduler - Registering RDD 3499 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 102
18:15:13.318 INFO  DAGScheduler - Registering RDD 3503 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 101
18:15:13.318 INFO  DAGScheduler - Got job 424 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:15:13.318 INFO  DAGScheduler - Final stage: ResultStage 740 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:15:13.318 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 739)
18:15:13.319 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 739)
18:15:13.319 INFO  DAGScheduler - Submitting ShuffleMapStage 737 (MapPartitionsRDD[3495] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:15:13.320 INFO  MemoryStore - Block broadcast_1377 stored as values in memory (estimated size 24.2 KiB, free 1902.6 MiB)
18:15:13.320 INFO  MemoryStore - Block broadcast_1377_piece0 stored as bytes in memory (estimated size 12.6 KiB, free 1902.6 MiB)
18:15:13.320 INFO  BlockManagerInfo - Added broadcast_1377_piece0 in memory on localhost:44275 (size: 12.6 KiB, free: 1918.8 MiB)
18:15:13.320 INFO  SparkContext - Created broadcast 1377 from broadcast at DAGScheduler.scala:1580
18:15:13.321 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 737 (MapPartitionsRDD[3495] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:15:13.321 INFO  TaskSchedulerImpl - Adding task set 737.0 with 1 tasks resource profile 0
18:15:13.321 INFO  TaskSetManager - Starting task 0.0 in stage 737.0 (TID 678) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:15:13.322 INFO  Executor - Running task 0.0 in stage 737.0 (TID 678)
18:15:13.323 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.323 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.326 INFO  Executor - Finished task 0.0 in stage 737.0 (TID 678). 1922 bytes result sent to driver
18:15:13.327 INFO  TaskSetManager - Finished task 0.0 in stage 737.0 (TID 678) in 6 ms on localhost (executor driver) (1/1)
18:15:13.327 INFO  TaskSchedulerImpl - Removed TaskSet 737.0, whose tasks have all completed, from pool 
18:15:13.327 INFO  DAGScheduler - ShuffleMapStage 737 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.008 s
18:15:13.327 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.327 INFO  DAGScheduler - running: HashSet()
18:15:13.327 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 738, ShuffleMapStage 739, ResultStage 740)
18:15:13.327 INFO  DAGScheduler - failed: HashSet()
18:15:13.327 INFO  DAGScheduler - Submitting ShuffleMapStage 738 (MapPartitionsRDD[3499] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:15:13.328 INFO  MemoryStore - Block broadcast_1378 stored as values in memory (estimated size 28.3 KiB, free 1902.6 MiB)
18:15:13.329 INFO  MemoryStore - Block broadcast_1378_piece0 stored as bytes in memory (estimated size 14.8 KiB, free 1902.6 MiB)
18:15:13.329 INFO  BlockManagerInfo - Added broadcast_1378_piece0 in memory on localhost:44275 (size: 14.8 KiB, free: 1918.8 MiB)
18:15:13.329 INFO  SparkContext - Created broadcast 1378 from broadcast at DAGScheduler.scala:1580
18:15:13.329 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 738 (MapPartitionsRDD[3499] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:15:13.329 INFO  TaskSchedulerImpl - Adding task set 738.0 with 1 tasks resource profile 0
18:15:13.330 INFO  TaskSetManager - Starting task 0.0 in stage 738.0 (TID 679) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:15:13.330 INFO  Executor - Running task 0.0 in stage 738.0 (TID 679)
18:15:13.331 INFO  ShuffleBlockFetcherIterator - Getting 1 (129.0 B) non-empty blocks including 1 (129.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.332 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.336 INFO  Executor - Finished task 0.0 in stage 738.0 (TID 679). 1922 bytes result sent to driver
18:15:13.336 INFO  TaskSetManager - Finished task 0.0 in stage 738.0 (TID 679) in 6 ms on localhost (executor driver) (1/1)
18:15:13.336 INFO  TaskSchedulerImpl - Removed TaskSet 738.0, whose tasks have all completed, from pool 
18:15:13.336 INFO  DAGScheduler - ShuffleMapStage 738 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.008 s
18:15:13.336 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.336 INFO  DAGScheduler - running: HashSet()
18:15:13.336 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 739, ResultStage 740)
18:15:13.337 INFO  DAGScheduler - failed: HashSet()
18:15:13.337 INFO  DAGScheduler - Submitting ShuffleMapStage 739 (MapPartitionsRDD[3503] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:15:13.337 INFO  MemoryStore - Block broadcast_1379 stored as values in memory (estimated size 19.0 KiB, free 1902.5 MiB)
18:15:13.338 INFO  MemoryStore - Block broadcast_1379_piece0 stored as bytes in memory (estimated size 9.7 KiB, free 1902.5 MiB)
18:15:13.338 INFO  BlockManagerInfo - Added broadcast_1379_piece0 in memory on localhost:44275 (size: 9.7 KiB, free: 1918.7 MiB)
18:15:13.338 INFO  SparkContext - Created broadcast 1379 from broadcast at DAGScheduler.scala:1580
18:15:13.338 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 739 (MapPartitionsRDD[3503] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:15:13.338 INFO  TaskSchedulerImpl - Adding task set 739.0 with 1 tasks resource profile 0
18:15:13.339 INFO  TaskSetManager - Starting task 0.0 in stage 739.0 (TID 680) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:13.339 INFO  Executor - Running task 0.0 in stage 739.0 (TID 680)
18:15:13.341 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.341 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.343 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.343 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.344 INFO  Executor - Finished task 0.0 in stage 739.0 (TID 680). 1922 bytes result sent to driver
18:15:13.344 INFO  TaskSetManager - Finished task 0.0 in stage 739.0 (TID 680) in 5 ms on localhost (executor driver) (1/1)
18:15:13.344 INFO  TaskSchedulerImpl - Removed TaskSet 739.0, whose tasks have all completed, from pool 
18:15:13.345 INFO  DAGScheduler - ShuffleMapStage 739 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.008 s
18:15:13.345 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.345 INFO  DAGScheduler - running: HashSet()
18:15:13.345 INFO  DAGScheduler - waiting: HashSet(ResultStage 740)
18:15:13.345 INFO  DAGScheduler - failed: HashSet()
18:15:13.345 INFO  DAGScheduler - Submitting ResultStage 740 (MapPartitionsRDD[3505] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:15:13.346 INFO  MemoryStore - Block broadcast_1380 stored as values in memory (estimated size 20.2 KiB, free 1902.5 MiB)
18:15:13.346 INFO  MemoryStore - Block broadcast_1380_piece0 stored as bytes in memory (estimated size 10.6 KiB, free 1902.5 MiB)
18:15:13.346 INFO  BlockManagerInfo - Added broadcast_1380_piece0 in memory on localhost:44275 (size: 10.6 KiB, free: 1918.7 MiB)
18:15:13.347 INFO  SparkContext - Created broadcast 1380 from broadcast at DAGScheduler.scala:1580
18:15:13.347 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 740 (MapPartitionsRDD[3505] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:15:13.347 INFO  TaskSchedulerImpl - Adding task set 740.0 with 1 tasks resource profile 0
18:15:13.347 INFO  TaskSetManager - Starting task 0.0 in stage 740.0 (TID 681) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:13.348 INFO  Executor - Running task 0.0 in stage 740.0 (TID 681)
18:15:13.349 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.349 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.351 INFO  Executor - Finished task 0.0 in stage 740.0 (TID 681). 1901 bytes result sent to driver
18:15:13.351 INFO  TaskSetManager - Finished task 0.0 in stage 740.0 (TID 681) in 4 ms on localhost (executor driver) (1/1)
18:15:13.351 INFO  TaskSchedulerImpl - Removed TaskSet 740.0, whose tasks have all completed, from pool 
18:15:13.351 INFO  DAGScheduler - ResultStage 740 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.006 s
18:15:13.351 INFO  DAGScheduler - Job 424 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:13.351 INFO  TaskSchedulerImpl - Killing all running tasks in stage 740: Stage finished
18:15:13.352 INFO  DAGScheduler - Job 424 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.034182 s
18:15:13.366 INFO  MemoryStore - Block broadcast_1381 stored as values in memory (estimated size 20.3 KiB, free 1902.5 MiB)
18:15:13.367 INFO  MemoryStore - Block broadcast_1381_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1902.5 MiB)
18:15:13.367 INFO  BlockManagerInfo - Added broadcast_1381_piece0 in memory on localhost:44275 (size: 1850.0 B, free: 1918.7 MiB)
18:15:13.367 INFO  SparkContext - Created broadcast 1381 from broadcast at ReadsSparkSink.java:133
18:15:13.368 INFO  MemoryStore - Block broadcast_1382 stored as values in memory (estimated size 20.4 KiB, free 1902.5 MiB)
18:15:13.368 INFO  MemoryStore - Block broadcast_1382_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1902.5 MiB)
18:15:13.368 INFO  BlockManagerInfo - Added broadcast_1382_piece0 in memory on localhost:44275 (size: 1850.0 B, free: 1918.7 MiB)
18:15:13.369 INFO  SparkContext - Created broadcast 1382 from broadcast at BamSink.java:76
18:15:13.371 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:15:13.371 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:13.371 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:13.387 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:15:13.388 INFO  DAGScheduler - Registering RDD 3507 (mapToPair at SparkUtils.java:161) as input to shuffle 104
18:15:13.388 INFO  DAGScheduler - Got job 425 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:15:13.388 INFO  DAGScheduler - Final stage: ResultStage 745 (runJob at SparkHadoopWriter.scala:83)
18:15:13.388 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 744)
18:15:13.388 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 744)
18:15:13.388 INFO  DAGScheduler - Submitting ShuffleMapStage 744 (MapPartitionsRDD[3507] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:13.389 INFO  MemoryStore - Block broadcast_1383 stored as values in memory (estimated size 18.1 KiB, free 1902.4 MiB)
18:15:13.390 INFO  MemoryStore - Block broadcast_1383_piece0 stored as bytes in memory (estimated size 9.5 KiB, free 1902.4 MiB)
18:15:13.390 INFO  BlockManagerInfo - Added broadcast_1383_piece0 in memory on localhost:44275 (size: 9.5 KiB, free: 1918.7 MiB)
18:15:13.390 INFO  SparkContext - Created broadcast 1383 from broadcast at DAGScheduler.scala:1580
18:15:13.390 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 744 (MapPartitionsRDD[3507] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:13.390 INFO  TaskSchedulerImpl - Adding task set 744.0 with 1 tasks resource profile 0
18:15:13.391 INFO  TaskSetManager - Starting task 0.0 in stage 744.0 (TID 682) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:13.391 INFO  Executor - Running task 0.0 in stage 744.0 (TID 682)
18:15:13.393 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.393 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.395 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.395 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.397 INFO  Executor - Finished task 0.0 in stage 744.0 (TID 682). 1922 bytes result sent to driver
18:15:13.397 INFO  TaskSetManager - Finished task 0.0 in stage 744.0 (TID 682) in 6 ms on localhost (executor driver) (1/1)
18:15:13.397 INFO  TaskSchedulerImpl - Removed TaskSet 744.0, whose tasks have all completed, from pool 
18:15:13.397 INFO  DAGScheduler - ShuffleMapStage 744 (mapToPair at SparkUtils.java:161) finished in 0.008 s
18:15:13.397 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.397 INFO  DAGScheduler - running: HashSet()
18:15:13.397 INFO  DAGScheduler - waiting: HashSet(ResultStage 745)
18:15:13.397 INFO  DAGScheduler - failed: HashSet()
18:15:13.398 INFO  DAGScheduler - Submitting ResultStage 745 (MapPartitionsRDD[3512] at mapToPair at BamSink.java:91), which has no missing parents
18:15:13.404 INFO  MemoryStore - Block broadcast_1384 stored as values in memory (estimated size 163.7 KiB, free 1902.3 MiB)
18:15:13.406 INFO  MemoryStore - Block broadcast_1384_piece0 stored as bytes in memory (estimated size 73.9 KiB, free 1902.2 MiB)
18:15:13.406 INFO  BlockManagerInfo - Added broadcast_1384_piece0 in memory on localhost:44275 (size: 73.9 KiB, free: 1918.7 MiB)
18:15:13.406 INFO  SparkContext - Created broadcast 1384 from broadcast at DAGScheduler.scala:1580
18:15:13.406 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 745 (MapPartitionsRDD[3512] at mapToPair at BamSink.java:91) (first 15 tasks are for partitions Vector(0))
18:15:13.406 INFO  TaskSchedulerImpl - Adding task set 745.0 with 1 tasks resource profile 0
18:15:13.406 INFO  TaskSetManager - Starting task 0.0 in stage 745.0 (TID 683) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:13.407 INFO  Executor - Running task 0.0 in stage 745.0 (TID 683)
18:15:13.410 INFO  ShuffleBlockFetcherIterator - Getting 1 (405.0 B) non-empty blocks including 1 (405.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.410 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.413 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:15:13.413 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:13.413 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:13.413 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:15:13.413 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:13.413 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:13.432 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271815137751540667173470666_3512_r_000000_0' to file:/tmp/local1968013552877906910/markdups842866711268961729.bam.parts/_temporary/0/task_202505271815137751540667173470666_3512_r_000000
18:15:13.432 INFO  SparkHadoopMapRedUtil - attempt_202505271815137751540667173470666_3512_r_000000_0: Committed. Elapsed time: 0 ms.
18:15:13.433 INFO  Executor - Finished task 0.0 in stage 745.0 (TID 683). 1858 bytes result sent to driver
18:15:13.433 INFO  TaskSetManager - Finished task 0.0 in stage 745.0 (TID 683) in 27 ms on localhost (executor driver) (1/1)
18:15:13.433 INFO  TaskSchedulerImpl - Removed TaskSet 745.0, whose tasks have all completed, from pool 
18:15:13.433 INFO  DAGScheduler - ResultStage 745 (runJob at SparkHadoopWriter.scala:83) finished in 0.035 s
18:15:13.433 INFO  DAGScheduler - Job 425 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:13.433 INFO  TaskSchedulerImpl - Killing all running tasks in stage 745: Stage finished
18:15:13.433 INFO  DAGScheduler - Job 425 finished: runJob at SparkHadoopWriter.scala:83, took 0.046091 s
18:15:13.434 INFO  SparkHadoopWriter - Start to commit write Job job_202505271815137751540667173470666_3512.
18:15:13.438 INFO  SparkHadoopWriter - Write Job job_202505271815137751540667173470666_3512 committed. Elapsed time: 4 ms.
18:15:13.449 INFO  HadoopFileSystemWrapper - Concatenating 3 parts to /tmp/local1968013552877906910/markdups842866711268961729.bam
18:15:13.452 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/local1968013552877906910/markdups842866711268961729.bam done
18:15:13.453 INFO  IndexFileMerger - Merging .sbi files in temp directory /tmp/local1968013552877906910/markdups842866711268961729.bam.parts/ to /tmp/local1968013552877906910/markdups842866711268961729.bam.sbi
18:15:13.457 INFO  IndexFileMerger - Done merging .sbi files
18:15:13.457 INFO  IndexFileMerger - Merging .bai files in temp directory /tmp/local1968013552877906910/markdups842866711268961729.bam.parts/ to /tmp/local1968013552877906910/markdups842866711268961729.bam.bai
18:15:13.461 INFO  IndexFileMerger - Done merging .bai files
18:15:13.461 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:15:13 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1432354816
18:15:13.470 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:13.471 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:15:13.471 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:15:13.471 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:15:13.471 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:15:13.471 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:15:13 PM UTC
18:15:13.471 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:13.471 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:13.471 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:15:13.471 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:15:13.471 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:15:13.471 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:15:13.471 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:15:13.471 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:15:13.471 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:15:13.471 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:15:13.471 INFO  MarkDuplicatesSpark - Initializing engine
18:15:13.471 INFO  MarkDuplicatesSpark - Done initializing engine
18:15:13.471 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:15:13.474 INFO  MemoryStore - Block broadcast_1385 stored as values in memory (estimated size 306.3 KiB, free 1901.9 MiB)
18:15:13.484 INFO  MemoryStore - Block broadcast_1385_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1901.8 MiB)
18:15:13.484 INFO  BlockManagerInfo - Added broadcast_1385_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1918.6 MiB)
18:15:13.485 INFO  SparkContext - Created broadcast 1385 from newAPIHadoopFile at PathSplitSource.java:96
18:15:13.504 INFO  MemoryStore - Block broadcast_1386 stored as values in memory (estimated size 306.3 KiB, free 1901.5 MiB)
18:15:13.510 INFO  MemoryStore - Block broadcast_1386_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1901.5 MiB)
18:15:13.510 INFO  BlockManagerInfo - Added broadcast_1386_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1918.5 MiB)
18:15:13.511 INFO  SparkContext - Created broadcast 1386 from newAPIHadoopFile at PathSplitSource.java:96
18:15:13.543 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:15:13.543 INFO  FileInputFormat - Total input files to process : 1
18:15:13.544 INFO  DAGScheduler - Registering RDD 3526 (mapToPair at SparkUtils.java:161) as input to shuffle 105
18:15:13.544 INFO  DAGScheduler - Got job 426 (collect at SparkUtils.java:205) with 1 output partitions
18:15:13.544 INFO  DAGScheduler - Final stage: ResultStage 747 (collect at SparkUtils.java:205)
18:15:13.544 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 746)
18:15:13.544 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 746)
18:15:13.544 INFO  DAGScheduler - Submitting ShuffleMapStage 746 (MapPartitionsRDD[3526] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:13.560 INFO  MemoryStore - Block broadcast_1387 stored as values in memory (estimated size 460.4 KiB, free 1901.0 MiB)
18:15:13.563 INFO  MemoryStore - Block broadcast_1387_piece0 stored as bytes in memory (estimated size 202.5 KiB, free 1900.8 MiB)
18:15:13.563 INFO  BlockManagerInfo - Added broadcast_1387_piece0 in memory on localhost:44275 (size: 202.5 KiB, free: 1918.3 MiB)
18:15:13.563 INFO  SparkContext - Created broadcast 1387 from broadcast at DAGScheduler.scala:1580
18:15:13.563 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 746 (MapPartitionsRDD[3526] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:13.563 INFO  TaskSchedulerImpl - Adding task set 746.0 with 1 tasks resource profile 0
18:15:13.564 INFO  TaskSetManager - Starting task 0.0 in stage 746.0 (TID 684) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9736 bytes) 
18:15:13.564 INFO  Executor - Running task 0.0 in stage 746.0 (TID 684)
18:15:13.592 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug2.bam:0+1856
18:15:13.596 INFO  Executor - Finished task 0.0 in stage 746.0 (TID 684). 1148 bytes result sent to driver
18:15:13.596 INFO  TaskSetManager - Finished task 0.0 in stage 746.0 (TID 684) in 32 ms on localhost (executor driver) (1/1)
18:15:13.596 INFO  TaskSchedulerImpl - Removed TaskSet 746.0, whose tasks have all completed, from pool 
18:15:13.596 INFO  DAGScheduler - ShuffleMapStage 746 (mapToPair at SparkUtils.java:161) finished in 0.052 s
18:15:13.596 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.596 INFO  DAGScheduler - running: HashSet()
18:15:13.596 INFO  DAGScheduler - waiting: HashSet(ResultStage 747)
18:15:13.596 INFO  DAGScheduler - failed: HashSet()
18:15:13.596 INFO  DAGScheduler - Submitting ResultStage 747 (MapPartitionsRDD[3529] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:15:13.597 INFO  MemoryStore - Block broadcast_1388 stored as values in memory (estimated size 7.4 KiB, free 1900.8 MiB)
18:15:13.597 INFO  MemoryStore - Block broadcast_1388_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1900.8 MiB)
18:15:13.597 INFO  BlockManagerInfo - Added broadcast_1388_piece0 in memory on localhost:44275 (size: 4.1 KiB, free: 1918.3 MiB)
18:15:13.598 INFO  SparkContext - Created broadcast 1388 from broadcast at DAGScheduler.scala:1580
18:15:13.598 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 747 (MapPartitionsRDD[3529] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:15:13.598 INFO  TaskSchedulerImpl - Adding task set 747.0 with 1 tasks resource profile 0
18:15:13.598 INFO  TaskSetManager - Starting task 0.0 in stage 747.0 (TID 685) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:13.598 INFO  Executor - Running task 0.0 in stage 747.0 (TID 685)
18:15:13.599 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.599 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.601 INFO  Executor - Finished task 0.0 in stage 747.0 (TID 685). 2495 bytes result sent to driver
18:15:13.601 INFO  TaskSetManager - Finished task 0.0 in stage 747.0 (TID 685) in 3 ms on localhost (executor driver) (1/1)
18:15:13.601 INFO  TaskSchedulerImpl - Removed TaskSet 747.0, whose tasks have all completed, from pool 
18:15:13.601 INFO  DAGScheduler - ResultStage 747 (collect at SparkUtils.java:205) finished in 0.004 s
18:15:13.601 INFO  DAGScheduler - Job 426 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:13.602 INFO  TaskSchedulerImpl - Killing all running tasks in stage 747: Stage finished
18:15:13.602 INFO  DAGScheduler - Job 426 finished: collect at SparkUtils.java:205, took 0.058816 s
18:15:13.606 INFO  MemoryStore - Block broadcast_1389 stored as values in memory (estimated size 1632.0 B, free 1900.8 MiB)
18:15:13.606 INFO  MemoryStore - Block broadcast_1389_piece0 stored as bytes in memory (estimated size 145.0 B, free 1900.8 MiB)
18:15:13.606 INFO  BlockManagerInfo - Added broadcast_1389_piece0 in memory on localhost:44275 (size: 145.0 B, free: 1918.3 MiB)
18:15:13.607 INFO  SparkContext - Created broadcast 1389 from broadcast at MarkDuplicatesSparkUtils.java:126
18:15:13.607 INFO  MemoryStore - Block broadcast_1390 stored as values in memory (estimated size 304.0 B, free 1900.8 MiB)
18:15:13.607 INFO  MemoryStore - Block broadcast_1390_piece0 stored as bytes in memory (estimated size 37.0 B, free 1900.8 MiB)
18:15:13.607 INFO  BlockManagerInfo - Added broadcast_1390_piece0 in memory on localhost:44275 (size: 37.0 B, free: 1918.3 MiB)
18:15:13.607 INFO  SparkContext - Created broadcast 1390 from broadcast at MarkDuplicatesSparkUtils.java:127
18:15:13.619 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:15:13.620 INFO  DAGScheduler - Registering RDD 3538 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 108
18:15:13.620 INFO  DAGScheduler - Registering RDD 3542 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 107
18:15:13.620 INFO  DAGScheduler - Registering RDD 3546 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 106
18:15:13.620 INFO  DAGScheduler - Got job 427 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:15:13.620 INFO  DAGScheduler - Final stage: ResultStage 752 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:15:13.620 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 751)
18:15:13.620 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 751)
18:15:13.621 INFO  DAGScheduler - Submitting ShuffleMapStage 749 (MapPartitionsRDD[3538] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:15:13.621 INFO  MemoryStore - Block broadcast_1391 stored as values in memory (estimated size 24.2 KiB, free 1900.8 MiB)
18:15:13.622 INFO  MemoryStore - Block broadcast_1391_piece0 stored as bytes in memory (estimated size 12.6 KiB, free 1900.8 MiB)
18:15:13.622 INFO  BlockManagerInfo - Added broadcast_1391_piece0 in memory on localhost:44275 (size: 12.6 KiB, free: 1918.3 MiB)
18:15:13.622 INFO  SparkContext - Created broadcast 1391 from broadcast at DAGScheduler.scala:1580
18:15:13.622 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 749 (MapPartitionsRDD[3538] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:15:13.622 INFO  TaskSchedulerImpl - Adding task set 749.0 with 1 tasks resource profile 0
18:15:13.623 INFO  TaskSetManager - Starting task 0.0 in stage 749.0 (TID 686) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:15:13.623 INFO  Executor - Running task 0.0 in stage 749.0 (TID 686)
18:15:13.625 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.625 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.628 INFO  Executor - Finished task 0.0 in stage 749.0 (TID 686). 1922 bytes result sent to driver
18:15:13.628 INFO  TaskSetManager - Finished task 0.0 in stage 749.0 (TID 686) in 5 ms on localhost (executor driver) (1/1)
18:15:13.628 INFO  TaskSchedulerImpl - Removed TaskSet 749.0, whose tasks have all completed, from pool 
18:15:13.628 INFO  DAGScheduler - ShuffleMapStage 749 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.007 s
18:15:13.628 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.628 INFO  DAGScheduler - running: HashSet()
18:15:13.628 INFO  DAGScheduler - waiting: HashSet(ResultStage 752, ShuffleMapStage 750, ShuffleMapStage 751)
18:15:13.629 INFO  DAGScheduler - failed: HashSet()
18:15:13.629 INFO  DAGScheduler - Submitting ShuffleMapStage 750 (MapPartitionsRDD[3542] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:15:13.629 INFO  MemoryStore - Block broadcast_1392 stored as values in memory (estimated size 28.3 KiB, free 1900.7 MiB)
18:15:13.630 INFO  MemoryStore - Block broadcast_1392_piece0 stored as bytes in memory (estimated size 14.8 KiB, free 1900.7 MiB)
18:15:13.630 INFO  BlockManagerInfo - Added broadcast_1392_piece0 in memory on localhost:44275 (size: 14.8 KiB, free: 1918.3 MiB)
18:15:13.630 INFO  SparkContext - Created broadcast 1392 from broadcast at DAGScheduler.scala:1580
18:15:13.630 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 750 (MapPartitionsRDD[3542] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:15:13.630 INFO  TaskSchedulerImpl - Adding task set 750.0 with 1 tasks resource profile 0
18:15:13.631 INFO  TaskSetManager - Starting task 0.0 in stage 750.0 (TID 687) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:15:13.631 INFO  Executor - Running task 0.0 in stage 750.0 (TID 687)
18:15:13.632 INFO  ShuffleBlockFetcherIterator - Getting 1 (142.0 B) non-empty blocks including 1 (142.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.632 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.636 INFO  Executor - Finished task 0.0 in stage 750.0 (TID 687). 1879 bytes result sent to driver
18:15:13.636 INFO  TaskSetManager - Finished task 0.0 in stage 750.0 (TID 687) in 6 ms on localhost (executor driver) (1/1)
18:15:13.636 INFO  TaskSchedulerImpl - Removed TaskSet 750.0, whose tasks have all completed, from pool 
18:15:13.636 INFO  DAGScheduler - ShuffleMapStage 750 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.007 s
18:15:13.636 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.636 INFO  DAGScheduler - running: HashSet()
18:15:13.637 INFO  DAGScheduler - waiting: HashSet(ResultStage 752, ShuffleMapStage 751)
18:15:13.637 INFO  DAGScheduler - failed: HashSet()
18:15:13.637 INFO  DAGScheduler - Submitting ShuffleMapStage 751 (MapPartitionsRDD[3546] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:15:13.637 INFO  MemoryStore - Block broadcast_1393 stored as values in memory (estimated size 19.0 KiB, free 1900.7 MiB)
18:15:13.638 INFO  MemoryStore - Block broadcast_1393_piece0 stored as bytes in memory (estimated size 9.7 KiB, free 1900.7 MiB)
18:15:13.638 INFO  BlockManagerInfo - Added broadcast_1393_piece0 in memory on localhost:44275 (size: 9.7 KiB, free: 1918.3 MiB)
18:15:13.638 INFO  SparkContext - Created broadcast 1393 from broadcast at DAGScheduler.scala:1580
18:15:13.638 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 751 (MapPartitionsRDD[3546] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:15:13.638 INFO  TaskSchedulerImpl - Adding task set 751.0 with 1 tasks resource profile 0
18:15:13.638 INFO  TaskSetManager - Starting task 0.0 in stage 751.0 (TID 688) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:13.639 INFO  Executor - Running task 0.0 in stage 751.0 (TID 688)
18:15:13.640 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.640 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.641 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.641 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.642 INFO  Executor - Finished task 0.0 in stage 751.0 (TID 688). 1879 bytes result sent to driver
18:15:13.643 INFO  TaskSetManager - Finished task 0.0 in stage 751.0 (TID 688) in 5 ms on localhost (executor driver) (1/1)
18:15:13.643 INFO  TaskSchedulerImpl - Removed TaskSet 751.0, whose tasks have all completed, from pool 
18:15:13.643 INFO  DAGScheduler - ShuffleMapStage 751 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.006 s
18:15:13.643 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.643 INFO  DAGScheduler - running: HashSet()
18:15:13.643 INFO  DAGScheduler - waiting: HashSet(ResultStage 752)
18:15:13.643 INFO  DAGScheduler - failed: HashSet()
18:15:13.643 INFO  DAGScheduler - Submitting ResultStage 752 (MapPartitionsRDD[3548] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:15:13.644 INFO  MemoryStore - Block broadcast_1394 stored as values in memory (estimated size 20.2 KiB, free 1900.7 MiB)
18:15:13.644 INFO  MemoryStore - Block broadcast_1394_piece0 stored as bytes in memory (estimated size 10.6 KiB, free 1900.7 MiB)
18:15:13.644 INFO  BlockManagerInfo - Added broadcast_1394_piece0 in memory on localhost:44275 (size: 10.6 KiB, free: 1918.3 MiB)
18:15:13.644 INFO  SparkContext - Created broadcast 1394 from broadcast at DAGScheduler.scala:1580
18:15:13.645 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 752 (MapPartitionsRDD[3548] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:15:13.645 INFO  TaskSchedulerImpl - Adding task set 752.0 with 1 tasks resource profile 0
18:15:13.645 INFO  TaskSetManager - Starting task 0.0 in stage 752.0 (TID 689) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:13.645 INFO  Executor - Running task 0.0 in stage 752.0 (TID 689)
18:15:13.646 INFO  ShuffleBlockFetcherIterator - Getting 1 (142.0 B) non-empty blocks including 1 (142.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.646 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.647 INFO  Executor - Finished task 0.0 in stage 752.0 (TID 689). 2010 bytes result sent to driver
18:15:13.648 INFO  TaskSetManager - Finished task 0.0 in stage 752.0 (TID 689) in 3 ms on localhost (executor driver) (1/1)
18:15:13.648 INFO  TaskSchedulerImpl - Removed TaskSet 752.0, whose tasks have all completed, from pool 
18:15:13.648 INFO  DAGScheduler - ResultStage 752 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.005 s
18:15:13.648 INFO  DAGScheduler - Job 427 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:13.648 INFO  TaskSchedulerImpl - Killing all running tasks in stage 752: Stage finished
18:15:13.648 INFO  DAGScheduler - Job 427 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.028726 s
18:15:13.658 INFO  MemoryStore - Block broadcast_1395 stored as values in memory (estimated size 20.3 KiB, free 1900.7 MiB)
18:15:13.659 INFO  MemoryStore - Block broadcast_1395_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1900.7 MiB)
18:15:13.659 INFO  BlockManagerInfo - Added broadcast_1395_piece0 in memory on localhost:44275 (size: 1850.0 B, free: 1918.3 MiB)
18:15:13.659 INFO  SparkContext - Created broadcast 1395 from broadcast at ReadsSparkSink.java:133
18:15:13.660 INFO  MemoryStore - Block broadcast_1396 stored as values in memory (estimated size 20.4 KiB, free 1900.6 MiB)
18:15:13.660 INFO  MemoryStore - Block broadcast_1396_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1900.6 MiB)
18:15:13.660 INFO  BlockManagerInfo - Added broadcast_1396_piece0 in memory on localhost:44275 (size: 1850.0 B, free: 1918.3 MiB)
18:15:13.660 INFO  SparkContext - Created broadcast 1396 from broadcast at BamSink.java:76
18:15:13.662 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:15:13.662 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:13.662 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:13.678 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:15:13.678 INFO  DAGScheduler - Registering RDD 3550 (mapToPair at SparkUtils.java:161) as input to shuffle 109
18:15:13.678 INFO  DAGScheduler - Got job 428 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:15:13.678 INFO  DAGScheduler - Final stage: ResultStage 757 (runJob at SparkHadoopWriter.scala:83)
18:15:13.678 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 756)
18:15:13.679 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 756)
18:15:13.679 INFO  DAGScheduler - Submitting ShuffleMapStage 756 (MapPartitionsRDD[3550] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:13.679 INFO  MemoryStore - Block broadcast_1397 stored as values in memory (estimated size 18.1 KiB, free 1900.6 MiB)
18:15:13.680 INFO  MemoryStore - Block broadcast_1397_piece0 stored as bytes in memory (estimated size 9.5 KiB, free 1900.6 MiB)
18:15:13.680 INFO  BlockManagerInfo - Added broadcast_1397_piece0 in memory on localhost:44275 (size: 9.5 KiB, free: 1918.3 MiB)
18:15:13.680 INFO  SparkContext - Created broadcast 1397 from broadcast at DAGScheduler.scala:1580
18:15:13.680 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 756 (MapPartitionsRDD[3550] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:13.680 INFO  TaskSchedulerImpl - Adding task set 756.0 with 1 tasks resource profile 0
18:15:13.681 INFO  TaskSetManager - Starting task 0.0 in stage 756.0 (TID 690) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:13.681 INFO  Executor - Running task 0.0 in stage 756.0 (TID 690)
18:15:13.683 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.683 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.684 INFO  ShuffleBlockFetcherIterator - Getting 1 (117.0 B) non-empty blocks including 1 (117.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.685 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.686 INFO  Executor - Finished task 0.0 in stage 756.0 (TID 690). 1922 bytes result sent to driver
18:15:13.686 INFO  TaskSetManager - Finished task 0.0 in stage 756.0 (TID 690) in 5 ms on localhost (executor driver) (1/1)
18:15:13.686 INFO  TaskSchedulerImpl - Removed TaskSet 756.0, whose tasks have all completed, from pool 
18:15:13.686 INFO  DAGScheduler - ShuffleMapStage 756 (mapToPair at SparkUtils.java:161) finished in 0.007 s
18:15:13.686 INFO  DAGScheduler - looking for newly runnable stages
18:15:13.686 INFO  DAGScheduler - running: HashSet()
18:15:13.686 INFO  DAGScheduler - waiting: HashSet(ResultStage 757)
18:15:13.686 INFO  DAGScheduler - failed: HashSet()
18:15:13.686 INFO  DAGScheduler - Submitting ResultStage 757 (MapPartitionsRDD[3555] at mapToPair at BamSink.java:91), which has no missing parents
18:15:13.692 INFO  MemoryStore - Block broadcast_1398 stored as values in memory (estimated size 163.7 KiB, free 1900.4 MiB)
18:15:13.693 INFO  MemoryStore - Block broadcast_1398_piece0 stored as bytes in memory (estimated size 73.9 KiB, free 1900.4 MiB)
18:15:13.694 INFO  BlockManagerInfo - Added broadcast_1398_piece0 in memory on localhost:44275 (size: 73.9 KiB, free: 1918.2 MiB)
18:15:13.694 INFO  SparkContext - Created broadcast 1398 from broadcast at DAGScheduler.scala:1580
18:15:13.694 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 757 (MapPartitionsRDD[3555] at mapToPair at BamSink.java:91) (first 15 tasks are for partitions Vector(0))
18:15:13.694 INFO  TaskSchedulerImpl - Adding task set 757.0 with 1 tasks resource profile 0
18:15:13.694 INFO  TaskSetManager - Starting task 0.0 in stage 757.0 (TID 691) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:13.694 INFO  Executor - Running task 0.0 in stage 757.0 (TID 691)
18:15:13.698 INFO  ShuffleBlockFetcherIterator - Getting 1 (868.0 B) non-empty blocks including 1 (868.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:13.698 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:13.700 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:15:13.700 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:13.700 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:13.700 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:15:13.700 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:13.700 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:13.718 INFO  FileOutputCommitter - Saved output of task 'attempt_20250527181513493253571985002979_3555_r_000000_0' to file:/tmp/local1968013552877906910/markdups13359951244850649838.bam.parts/_temporary/0/task_20250527181513493253571985002979_3555_r_000000
18:15:13.718 INFO  SparkHadoopMapRedUtil - attempt_20250527181513493253571985002979_3555_r_000000_0: Committed. Elapsed time: 0 ms.
18:15:13.718 INFO  Executor - Finished task 0.0 in stage 757.0 (TID 691). 1858 bytes result sent to driver
18:15:13.718 INFO  TaskSetManager - Finished task 0.0 in stage 757.0 (TID 691) in 24 ms on localhost (executor driver) (1/1)
18:15:13.719 INFO  TaskSchedulerImpl - Removed TaskSet 757.0, whose tasks have all completed, from pool 
18:15:13.719 INFO  DAGScheduler - ResultStage 757 (runJob at SparkHadoopWriter.scala:83) finished in 0.032 s
18:15:13.719 INFO  DAGScheduler - Job 428 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:13.719 INFO  TaskSchedulerImpl - Killing all running tasks in stage 757: Stage finished
18:15:13.719 INFO  DAGScheduler - Job 428 finished: runJob at SparkHadoopWriter.scala:83, took 0.040902 s
18:15:13.719 INFO  SparkHadoopWriter - Start to commit write Job job_20250527181513493253571985002979_3555.
18:15:13.723 INFO  SparkHadoopWriter - Write Job job_20250527181513493253571985002979_3555 committed. Elapsed time: 4 ms.
18:15:13.733 INFO  HadoopFileSystemWrapper - Concatenating 3 parts to /tmp/local1968013552877906910/markdups13359951244850649838.bam
18:15:13.736 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/local1968013552877906910/markdups13359951244850649838.bam done
18:15:13.737 INFO  IndexFileMerger - Merging .sbi files in temp directory /tmp/local1968013552877906910/markdups13359951244850649838.bam.parts/ to /tmp/local1968013552877906910/markdups13359951244850649838.bam.sbi
18:15:13.741 INFO  IndexFileMerger - Done merging .sbi files
18:15:13.741 INFO  IndexFileMerger - Merging .bai files in temp directory /tmp/local1968013552877906910/markdups13359951244850649838.bam.parts/ to /tmp/local1968013552877906910/markdups13359951244850649838.bam.bai
18:15:13.746 INFO  IndexFileMerger - Done merging .bai files
18:15:13.746 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:15:13 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:14 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:14 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:14 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:15 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:15 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:15 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:17 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:18 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:18 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:18 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:19 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:19 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:19 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:21 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:22 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:22 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:23 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:23 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:23 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:24 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:25 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:26 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:26 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:27 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:27 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:27 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:28 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:29 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:30 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:30 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:31 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:31 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:31 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:32 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:33 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:34 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:34 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:35 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:37 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:37 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
18:15:37.956 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:37.956 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:15:37.956 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:15:37.956 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:15:37.956 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:15:37.956 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:15:37 PM UTC
18:15:37.956 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:37.956 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:37.956 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:15:37.956 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:15:37.956 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:15:37.956 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:15:37.956 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:15:37.956 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:15:37.956 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:15:37.956 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:15:37.956 INFO  MarkDuplicatesSpark - Initializing engine
18:15:37.956 INFO  MarkDuplicatesSpark - Done initializing engine
18:15:37.957 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:15:37.959 INFO  MemoryStore - Block broadcast_1975 stored as values in memory (estimated size 306.3 KiB, free 1918.3 MiB)
18:15:37.965 INFO  MemoryStore - Block broadcast_1975_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1918.2 MiB)
18:15:37.965 INFO  BlockManagerInfo - Added broadcast_1975_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1919.6 MiB)
18:15:37.966 INFO  SparkContext - Created broadcast 1975 from newAPIHadoopFile at PathSplitSource.java:96
18:15:37.986 INFO  MemoryStore - Block broadcast_1976 stored as values in memory (estimated size 306.3 KiB, free 1917.9 MiB)
18:15:37.992 INFO  MemoryStore - Block broadcast_1976_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1917.9 MiB)
18:15:37.992 INFO  BlockManagerInfo - Added broadcast_1976_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1919.6 MiB)
18:15:37.993 INFO  SparkContext - Created broadcast 1976 from newAPIHadoopFile at PathSplitSource.java:96
18:15:38.025 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:15:38.025 INFO  FileInputFormat - Total input files to process : 1
18:15:38.026 INFO  DAGScheduler - Registering RDD 5447 (mapToPair at SparkUtils.java:161) as input to shuffle 300
18:15:38.026 INFO  DAGScheduler - Got job 559 (collect at SparkUtils.java:205) with 1 output partitions
18:15:38.026 INFO  DAGScheduler - Final stage: ResultStage 1219 (collect at SparkUtils.java:205)
18:15:38.026 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1218)
18:15:38.026 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1218)
18:15:38.026 INFO  DAGScheduler - Submitting ShuffleMapStage 1218 (MapPartitionsRDD[5447] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:38.043 INFO  MemoryStore - Block broadcast_1977 stored as values in memory (estimated size 493.8 KiB, free 1917.4 MiB)
18:15:38.045 INFO  MemoryStore - Block broadcast_1977_piece0 stored as bytes in memory (estimated size 210.1 KiB, free 1917.2 MiB)
18:15:38.045 INFO  BlockManagerInfo - Added broadcast_1977_piece0 in memory on localhost:44275 (size: 210.1 KiB, free: 1919.4 MiB)
18:15:38.045 INFO  SparkContext - Created broadcast 1977 from broadcast at DAGScheduler.scala:1580
18:15:38.046 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1218 (MapPartitionsRDD[5447] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:38.046 INFO  TaskSchedulerImpl - Adding task set 1218.0 with 1 tasks resource profile 0
18:15:38.046 INFO  TaskSetManager - Starting task 0.0 in stage 1218.0 (TID 1062) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9758 bytes) 
18:15:38.046 INFO  Executor - Running task 0.0 in stage 1218.0 (TID 1062)
18:15:38.075 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/example.chr1.1-1K.unmarkedDups.bam:0+13412
18:15:38.080 INFO  Executor - Finished task 0.0 in stage 1218.0 (TID 1062). 1148 bytes result sent to driver
18:15:38.081 INFO  TaskSetManager - Finished task 0.0 in stage 1218.0 (TID 1062) in 35 ms on localhost (executor driver) (1/1)
18:15:38.081 INFO  TaskSchedulerImpl - Removed TaskSet 1218.0, whose tasks have all completed, from pool 
18:15:38.081 INFO  DAGScheduler - ShuffleMapStage 1218 (mapToPair at SparkUtils.java:161) finished in 0.055 s
18:15:38.081 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.081 INFO  DAGScheduler - running: HashSet()
18:15:38.081 INFO  DAGScheduler - waiting: HashSet(ResultStage 1219)
18:15:38.081 INFO  DAGScheduler - failed: HashSet()
18:15:38.081 INFO  DAGScheduler - Submitting ResultStage 1219 (MapPartitionsRDD[5450] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:15:38.082 INFO  MemoryStore - Block broadcast_1978 stored as values in memory (estimated size 7.4 KiB, free 1917.2 MiB)
18:15:38.082 INFO  MemoryStore - Block broadcast_1978_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1917.2 MiB)
18:15:38.082 INFO  BlockManagerInfo - Added broadcast_1978_piece0 in memory on localhost:44275 (size: 4.1 KiB, free: 1919.4 MiB)
18:15:38.082 INFO  SparkContext - Created broadcast 1978 from broadcast at DAGScheduler.scala:1580
18:15:38.082 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1219 (MapPartitionsRDD[5450] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:15:38.082 INFO  TaskSchedulerImpl - Adding task set 1219.0 with 1 tasks resource profile 0
18:15:38.083 INFO  TaskSetManager - Starting task 0.0 in stage 1219.0 (TID 1063) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.083 INFO  Executor - Running task 0.0 in stage 1219.0 (TID 1063)
18:15:38.084 INFO  ShuffleBlockFetcherIterator - Getting 1 (16.3 KiB) non-empty blocks including 1 (16.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.084 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.086 INFO  Executor - Finished task 0.0 in stage 1219.0 (TID 1063). 2329 bytes result sent to driver
18:15:38.087 INFO  TaskSetManager - Finished task 0.0 in stage 1219.0 (TID 1063) in 4 ms on localhost (executor driver) (1/1)
18:15:38.087 INFO  TaskSchedulerImpl - Removed TaskSet 1219.0, whose tasks have all completed, from pool 
18:15:38.087 INFO  DAGScheduler - ResultStage 1219 (collect at SparkUtils.java:205) finished in 0.006 s
18:15:38.087 INFO  DAGScheduler - Job 559 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.087 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1219: Stage finished
18:15:38.087 INFO  DAGScheduler - Job 559 finished: collect at SparkUtils.java:205, took 0.061827 s
18:15:38.091 INFO  MemoryStore - Block broadcast_1979 stored as values in memory (estimated size 7.8 KiB, free 1917.2 MiB)
18:15:38.091 INFO  MemoryStore - Block broadcast_1979_piece0 stored as bytes in memory (estimated size 540.0 B, free 1917.2 MiB)
18:15:38.091 INFO  BlockManagerInfo - Added broadcast_1979_piece0 in memory on localhost:44275 (size: 540.0 B, free: 1919.4 MiB)
18:15:38.092 INFO  SparkContext - Created broadcast 1979 from broadcast at MarkDuplicatesSparkUtils.java:126
18:15:38.092 INFO  MemoryStore - Block broadcast_1980 stored as values in memory (estimated size 2.6 KiB, free 1917.2 MiB)
18:15:38.092 INFO  MemoryStore - Block broadcast_1980_piece0 stored as bytes in memory (estimated size 209.0 B, free 1917.2 MiB)
18:15:38.092 INFO  BlockManagerInfo - Added broadcast_1980_piece0 in memory on localhost:44275 (size: 209.0 B, free: 1919.4 MiB)
18:15:38.093 INFO  SparkContext - Created broadcast 1980 from broadcast at MarkDuplicatesSparkUtils.java:127
18:15:38.106 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:15:38.106 INFO  DAGScheduler - Registering RDD 5459 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 303
18:15:38.106 INFO  DAGScheduler - Registering RDD 5463 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 302
18:15:38.106 INFO  DAGScheduler - Registering RDD 5467 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 301
18:15:38.107 INFO  DAGScheduler - Got job 560 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:15:38.107 INFO  DAGScheduler - Final stage: ResultStage 1224 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:15:38.107 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1223)
18:15:38.107 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1223)
18:15:38.107 INFO  DAGScheduler - Submitting ShuffleMapStage 1221 (MapPartitionsRDD[5459] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:15:38.108 INFO  MemoryStore - Block broadcast_1981 stored as values in memory (estimated size 57.6 KiB, free 1917.1 MiB)
18:15:38.108 INFO  MemoryStore - Block broadcast_1981_piece0 stored as bytes in memory (estimated size 19.8 KiB, free 1917.1 MiB)
18:15:38.108 INFO  BlockManagerInfo - Added broadcast_1981_piece0 in memory on localhost:44275 (size: 19.8 KiB, free: 1919.4 MiB)
18:15:38.108 INFO  SparkContext - Created broadcast 1981 from broadcast at DAGScheduler.scala:1580
18:15:38.109 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1221 (MapPartitionsRDD[5459] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:15:38.109 INFO  TaskSchedulerImpl - Adding task set 1221.0 with 1 tasks resource profile 0
18:15:38.109 INFO  TaskSetManager - Starting task 0.0 in stage 1221.0 (TID 1064) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:15:38.109 INFO  Executor - Running task 0.0 in stage 1221.0 (TID 1064)
18:15:38.111 INFO  ShuffleBlockFetcherIterator - Getting 1 (16.3 KiB) non-empty blocks including 1 (16.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.111 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.115 INFO  Executor - Finished task 0.0 in stage 1221.0 (TID 1064). 1922 bytes result sent to driver
18:15:38.115 INFO  TaskSetManager - Finished task 0.0 in stage 1221.0 (TID 1064) in 6 ms on localhost (executor driver) (1/1)
18:15:38.115 INFO  TaskSchedulerImpl - Removed TaskSet 1221.0, whose tasks have all completed, from pool 
18:15:38.115 INFO  DAGScheduler - ShuffleMapStage 1221 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.008 s
18:15:38.115 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.115 INFO  DAGScheduler - running: HashSet()
18:15:38.115 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1222, ShuffleMapStage 1223, ResultStage 1224)
18:15:38.115 INFO  DAGScheduler - failed: HashSet()
18:15:38.115 INFO  DAGScheduler - Submitting ShuffleMapStage 1222 (MapPartitionsRDD[5463] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:15:38.117 INFO  MemoryStore - Block broadcast_1982 stored as values in memory (estimated size 61.7 KiB, free 1917.0 MiB)
18:15:38.117 INFO  MemoryStore - Block broadcast_1982_piece0 stored as bytes in memory (estimated size 22.0 KiB, free 1917.0 MiB)
18:15:38.117 INFO  BlockManagerInfo - Added broadcast_1982_piece0 in memory on localhost:44275 (size: 22.0 KiB, free: 1919.3 MiB)
18:15:38.118 INFO  SparkContext - Created broadcast 1982 from broadcast at DAGScheduler.scala:1580
18:15:38.118 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1222 (MapPartitionsRDD[5463] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:15:38.118 INFO  TaskSchedulerImpl - Adding task set 1222.0 with 1 tasks resource profile 0
18:15:38.118 INFO  TaskSetManager - Starting task 0.0 in stage 1222.0 (TID 1065) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:15:38.118 INFO  Executor - Running task 0.0 in stage 1222.0 (TID 1065)
18:15:38.121 INFO  ShuffleBlockFetcherIterator - Getting 1 (2.0 KiB) non-empty blocks including 1 (2.0 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.121 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.128 INFO  Executor - Finished task 0.0 in stage 1222.0 (TID 1065). 1922 bytes result sent to driver
18:15:38.128 INFO  TaskSetManager - Finished task 0.0 in stage 1222.0 (TID 1065) in 10 ms on localhost (executor driver) (1/1)
18:15:38.128 INFO  TaskSchedulerImpl - Removed TaskSet 1222.0, whose tasks have all completed, from pool 
18:15:38.128 INFO  DAGScheduler - ShuffleMapStage 1222 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.012 s
18:15:38.128 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.128 INFO  DAGScheduler - running: HashSet()
18:15:38.128 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1223, ResultStage 1224)
18:15:38.128 INFO  DAGScheduler - failed: HashSet()
18:15:38.129 INFO  DAGScheduler - Submitting ShuffleMapStage 1223 (MapPartitionsRDD[5467] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:15:38.130 INFO  MemoryStore - Block broadcast_1983 stored as values in memory (estimated size 52.4 KiB, free 1916.9 MiB)
18:15:38.130 INFO  MemoryStore - Block broadcast_1983_piece0 stored as bytes in memory (estimated size 17.3 KiB, free 1916.9 MiB)
18:15:38.130 INFO  BlockManagerInfo - Added broadcast_1983_piece0 in memory on localhost:44275 (size: 17.3 KiB, free: 1919.3 MiB)
18:15:38.130 INFO  SparkContext - Created broadcast 1983 from broadcast at DAGScheduler.scala:1580
18:15:38.131 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1223 (MapPartitionsRDD[5467] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:15:38.131 INFO  TaskSchedulerImpl - Adding task set 1223.0 with 1 tasks resource profile 0
18:15:38.131 INFO  TaskSetManager - Starting task 0.0 in stage 1223.0 (TID 1066) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:38.131 INFO  Executor - Running task 0.0 in stage 1223.0 (TID 1066)
18:15:38.133 INFO  ShuffleBlockFetcherIterator - Getting 1 (16.3 KiB) non-empty blocks including 1 (16.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.133 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.136 INFO  ShuffleBlockFetcherIterator - Getting 1 (2.7 KiB) non-empty blocks including 1 (2.7 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.136 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.137 INFO  Executor - Finished task 0.0 in stage 1223.0 (TID 1066). 1922 bytes result sent to driver
18:15:38.138 INFO  TaskSetManager - Finished task 0.0 in stage 1223.0 (TID 1066) in 7 ms on localhost (executor driver) (1/1)
18:15:38.138 INFO  TaskSchedulerImpl - Removed TaskSet 1223.0, whose tasks have all completed, from pool 
18:15:38.138 INFO  DAGScheduler - ShuffleMapStage 1223 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.009 s
18:15:38.138 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.138 INFO  DAGScheduler - running: HashSet()
18:15:38.138 INFO  DAGScheduler - waiting: HashSet(ResultStage 1224)
18:15:38.138 INFO  DAGScheduler - failed: HashSet()
18:15:38.138 INFO  DAGScheduler - Submitting ResultStage 1224 (MapPartitionsRDD[5469] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:15:38.139 INFO  MemoryStore - Block broadcast_1984 stored as values in memory (estimated size 53.6 KiB, free 1916.9 MiB)
18:15:38.139 INFO  MemoryStore - Block broadcast_1984_piece0 stored as bytes in memory (estimated size 18.0 KiB, free 1916.9 MiB)
18:15:38.139 INFO  BlockManagerInfo - Added broadcast_1984_piece0 in memory on localhost:44275 (size: 18.0 KiB, free: 1919.3 MiB)
18:15:38.140 INFO  SparkContext - Created broadcast 1984 from broadcast at DAGScheduler.scala:1580
18:15:38.140 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1224 (MapPartitionsRDD[5469] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:15:38.140 INFO  TaskSchedulerImpl - Adding task set 1224.0 with 1 tasks resource profile 0
18:15:38.140 INFO  TaskSetManager - Starting task 0.0 in stage 1224.0 (TID 1067) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.140 INFO  Executor - Running task 0.0 in stage 1224.0 (TID 1067)
18:15:38.141 INFO  ShuffleBlockFetcherIterator - Getting 1 (251.0 B) non-empty blocks including 1 (251.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.141 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.143 INFO  Executor - Finished task 0.0 in stage 1224.0 (TID 1067). 2371 bytes result sent to driver
18:15:38.143 INFO  TaskSetManager - Finished task 0.0 in stage 1224.0 (TID 1067) in 3 ms on localhost (executor driver) (1/1)
18:15:38.143 INFO  TaskSchedulerImpl - Removed TaskSet 1224.0, whose tasks have all completed, from pool 
18:15:38.143 INFO  DAGScheduler - ResultStage 1224 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.005 s
18:15:38.143 INFO  DAGScheduler - Job 560 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.143 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1224: Stage finished
18:15:38.143 INFO  DAGScheduler - Job 560 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.037159 s
18:15:38.154 INFO  MemoryStore - Block broadcast_1985 stored as values in memory (estimated size 179.4 KiB, free 1916.7 MiB)
18:15:38.155 INFO  MemoryStore - Block broadcast_1985_piece0 stored as bytes in memory (estimated size 7.9 KiB, free 1916.7 MiB)
18:15:38.155 INFO  BlockManagerInfo - Added broadcast_1985_piece0 in memory on localhost:44275 (size: 7.9 KiB, free: 1919.3 MiB)
18:15:38.155 INFO  SparkContext - Created broadcast 1985 from broadcast at ReadsSparkSink.java:133
18:15:38.158 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:15:38.159 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:38.159 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:38.174 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:15:38.175 INFO  DAGScheduler - Registering RDD 5471 (mapToPair at SparkUtils.java:161) as input to shuffle 304
18:15:38.175 INFO  DAGScheduler - Got job 561 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:15:38.175 INFO  DAGScheduler - Final stage: ResultStage 1229 (runJob at SparkHadoopWriter.scala:83)
18:15:38.175 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1228)
18:15:38.175 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1228)
18:15:38.175 INFO  DAGScheduler - Submitting ShuffleMapStage 1228 (MapPartitionsRDD[5471] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:38.176 INFO  MemoryStore - Block broadcast_1986 stored as values in memory (estimated size 51.5 KiB, free 1916.6 MiB)
18:15:38.176 INFO  MemoryStore - Block broadcast_1986_piece0 stored as bytes in memory (estimated size 16.8 KiB, free 1916.6 MiB)
18:15:38.176 INFO  BlockManagerInfo - Added broadcast_1986_piece0 in memory on localhost:44275 (size: 16.8 KiB, free: 1919.3 MiB)
18:15:38.176 INFO  SparkContext - Created broadcast 1986 from broadcast at DAGScheduler.scala:1580
18:15:38.177 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1228 (MapPartitionsRDD[5471] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:38.177 INFO  TaskSchedulerImpl - Adding task set 1228.0 with 1 tasks resource profile 0
18:15:38.177 INFO  TaskSetManager - Starting task 0.0 in stage 1228.0 (TID 1068) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:38.177 INFO  Executor - Running task 0.0 in stage 1228.0 (TID 1068)
18:15:38.179 INFO  ShuffleBlockFetcherIterator - Getting 1 (16.3 KiB) non-empty blocks including 1 (16.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.179 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.181 INFO  ShuffleBlockFetcherIterator - Getting 1 (2.7 KiB) non-empty blocks including 1 (2.7 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.181 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.182 INFO  Executor - Finished task 0.0 in stage 1228.0 (TID 1068). 1922 bytes result sent to driver
18:15:38.183 INFO  TaskSetManager - Finished task 0.0 in stage 1228.0 (TID 1068) in 6 ms on localhost (executor driver) (1/1)
18:15:38.183 INFO  TaskSchedulerImpl - Removed TaskSet 1228.0, whose tasks have all completed, from pool 
18:15:38.183 INFO  DAGScheduler - ShuffleMapStage 1228 (mapToPair at SparkUtils.java:161) finished in 0.008 s
18:15:38.183 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.183 INFO  DAGScheduler - running: HashSet()
18:15:38.183 INFO  DAGScheduler - waiting: HashSet(ResultStage 1229)
18:15:38.183 INFO  DAGScheduler - failed: HashSet()
18:15:38.183 INFO  DAGScheduler - Submitting ResultStage 1229 (MapPartitionsRDD[5477] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:15:38.189 INFO  MemoryStore - Block broadcast_1987 stored as values in memory (estimated size 196.7 KiB, free 1916.4 MiB)
18:15:38.190 INFO  MemoryStore - Block broadcast_1987_piece0 stored as bytes in memory (estimated size 80.9 KiB, free 1916.3 MiB)
18:15:38.190 INFO  BlockManagerInfo - Added broadcast_1987_piece0 in memory on localhost:44275 (size: 80.9 KiB, free: 1919.2 MiB)
18:15:38.191 INFO  SparkContext - Created broadcast 1987 from broadcast at DAGScheduler.scala:1580
18:15:38.191 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1229 (MapPartitionsRDD[5477] at saveAsTextFile at SamSink.java:65) (first 15 tasks are for partitions Vector(0))
18:15:38.191 INFO  TaskSchedulerImpl - Adding task set 1229.0 with 1 tasks resource profile 0
18:15:38.191 INFO  TaskSetManager - Starting task 0.0 in stage 1229.0 (TID 1069) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.191 INFO  Executor - Running task 0.0 in stage 1229.0 (TID 1069)
18:15:38.194 INFO  ShuffleBlockFetcherIterator - Getting 1 (14.8 KiB) non-empty blocks including 1 (14.8 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.195 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.196 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:15:38.197 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:38.197 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:38.207 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271815386743197521430535506_5477_m_000000_0' to file:/tmp/MarkDups1827355161248595230/MarkDups.sam.parts/_temporary/0/task_202505271815386743197521430535506_5477_m_000000
18:15:38.207 INFO  SparkHadoopMapRedUtil - attempt_202505271815386743197521430535506_5477_m_000000_0: Committed. Elapsed time: 0 ms.
18:15:38.207 INFO  Executor - Finished task 0.0 in stage 1229.0 (TID 1069). 1858 bytes result sent to driver
18:15:38.208 INFO  TaskSetManager - Finished task 0.0 in stage 1229.0 (TID 1069) in 17 ms on localhost (executor driver) (1/1)
18:15:38.208 INFO  TaskSchedulerImpl - Removed TaskSet 1229.0, whose tasks have all completed, from pool 
18:15:38.208 INFO  DAGScheduler - ResultStage 1229 (runJob at SparkHadoopWriter.scala:83) finished in 0.025 s
18:15:38.208 INFO  DAGScheduler - Job 561 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.208 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1229: Stage finished
18:15:38.208 INFO  DAGScheduler - Job 561 finished: runJob at SparkHadoopWriter.scala:83, took 0.033660 s
18:15:38.208 INFO  SparkHadoopWriter - Start to commit write Job job_202505271815386743197521430535506_5477.
18:15:38.212 INFO  SparkHadoopWriter - Write Job job_202505271815386743197521430535506_5477 committed. Elapsed time: 3 ms.
18:15:38.219 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups1827355161248595230/MarkDups.sam
18:15:38.222 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups1827355161248595230/MarkDups.sam done
18:15:38.223 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:15:38 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
18:15:38.228 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:38.228 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:15:38.228 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:15:38.228 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:15:38.228 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:15:38.228 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:15:38 PM UTC
18:15:38.228 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:38.228 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:38.228 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:15:38.228 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:15:38.228 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:15:38.228 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:15:38.228 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:15:38.228 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:15:38.228 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:15:38.228 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:15:38.228 INFO  MarkDuplicatesSpark - Initializing engine
18:15:38.228 INFO  MarkDuplicatesSpark - Done initializing engine
18:15:38.229 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:15:38.230 INFO  MemoryStore - Block broadcast_1988 stored as values in memory (estimated size 306.3 KiB, free 1916.0 MiB)
18:15:38.237 INFO  MemoryStore - Block broadcast_1988_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1916.0 MiB)
18:15:38.237 INFO  BlockManagerInfo - Added broadcast_1988_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1919.1 MiB)
18:15:38.237 INFO  SparkContext - Created broadcast 1988 from newAPIHadoopFile at PathSplitSource.java:96
18:15:38.257 INFO  MemoryStore - Block broadcast_1989 stored as values in memory (estimated size 306.3 KiB, free 1915.7 MiB)
18:15:38.263 INFO  MemoryStore - Block broadcast_1989_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1915.6 MiB)
18:15:38.263 INFO  BlockManagerInfo - Added broadcast_1989_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1919.1 MiB)
18:15:38.263 INFO  SparkContext - Created broadcast 1989 from newAPIHadoopFile at PathSplitSource.java:96
18:15:38.295 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:15:38.295 INFO  FileInputFormat - Total input files to process : 1
18:15:38.296 INFO  DAGScheduler - Registering RDD 5491 (mapToPair at SparkUtils.java:161) as input to shuffle 305
18:15:38.296 INFO  DAGScheduler - Got job 562 (collect at SparkUtils.java:205) with 1 output partitions
18:15:38.296 INFO  DAGScheduler - Final stage: ResultStage 1231 (collect at SparkUtils.java:205)
18:15:38.296 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1230)
18:15:38.296 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1230)
18:15:38.296 INFO  DAGScheduler - Submitting ShuffleMapStage 1230 (MapPartitionsRDD[5491] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:38.312 INFO  MemoryStore - Block broadcast_1990 stored as values in memory (estimated size 457.4 KiB, free 1915.2 MiB)
18:15:38.315 INFO  MemoryStore - Block broadcast_1990_piece0 stored as bytes in memory (estimated size 201.1 KiB, free 1915.0 MiB)
18:15:38.315 INFO  BlockManagerInfo - Added broadcast_1990_piece0 in memory on localhost:44275 (size: 201.1 KiB, free: 1918.9 MiB)
18:15:38.315 INFO  SparkContext - Created broadcast 1990 from broadcast at DAGScheduler.scala:1580
18:15:38.315 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1230 (MapPartitionsRDD[5491] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:38.315 INFO  TaskSchedulerImpl - Adding task set 1230.0 with 1 tasks resource profile 0
18:15:38.315 INFO  TaskSetManager - Starting task 0.0 in stage 1230.0 (TID 1070) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9738 bytes) 
18:15:38.316 INFO  Executor - Running task 0.0 in stage 1230.0 (TID 1070)
18:15:38.344 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/optical_dupes.bam:0+678
18:15:38.347 INFO  Executor - Finished task 0.0 in stage 1230.0 (TID 1070). 1148 bytes result sent to driver
18:15:38.347 INFO  TaskSetManager - Finished task 0.0 in stage 1230.0 (TID 1070) in 32 ms on localhost (executor driver) (1/1)
18:15:38.348 INFO  TaskSchedulerImpl - Removed TaskSet 1230.0, whose tasks have all completed, from pool 
18:15:38.348 INFO  DAGScheduler - ShuffleMapStage 1230 (mapToPair at SparkUtils.java:161) finished in 0.052 s
18:15:38.348 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.348 INFO  DAGScheduler - running: HashSet()
18:15:38.348 INFO  DAGScheduler - waiting: HashSet(ResultStage 1231)
18:15:38.348 INFO  DAGScheduler - failed: HashSet()
18:15:38.348 INFO  DAGScheduler - Submitting ResultStage 1231 (MapPartitionsRDD[5494] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:15:38.348 INFO  MemoryStore - Block broadcast_1991 stored as values in memory (estimated size 7.4 KiB, free 1915.0 MiB)
18:15:38.349 INFO  MemoryStore - Block broadcast_1991_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1915.0 MiB)
18:15:38.349 INFO  BlockManagerInfo - Added broadcast_1991_piece0 in memory on localhost:44275 (size: 4.1 KiB, free: 1918.9 MiB)
18:15:38.349 INFO  SparkContext - Created broadcast 1991 from broadcast at DAGScheduler.scala:1580
18:15:38.349 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1231 (MapPartitionsRDD[5494] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:15:38.349 INFO  TaskSchedulerImpl - Adding task set 1231.0 with 1 tasks resource profile 0
18:15:38.349 INFO  TaskSetManager - Starting task 0.0 in stage 1231.0 (TID 1071) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.349 INFO  Executor - Running task 0.0 in stage 1231.0 (TID 1071)
18:15:38.350 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.350 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.351 INFO  Executor - Finished task 0.0 in stage 1231.0 (TID 1071). 2269 bytes result sent to driver
18:15:38.352 INFO  TaskSetManager - Finished task 0.0 in stage 1231.0 (TID 1071) in 2 ms on localhost (executor driver) (1/1)
18:15:38.352 INFO  TaskSchedulerImpl - Removed TaskSet 1231.0, whose tasks have all completed, from pool 
18:15:38.352 INFO  DAGScheduler - ResultStage 1231 (collect at SparkUtils.java:205) finished in 0.004 s
18:15:38.352 INFO  DAGScheduler - Job 562 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.352 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1231: Stage finished
18:15:38.352 INFO  DAGScheduler - Job 562 finished: collect at SparkUtils.java:205, took 0.056654 s
18:15:38.356 INFO  MemoryStore - Block broadcast_1992 stored as values in memory (estimated size 136.0 B, free 1915.0 MiB)
18:15:38.356 INFO  MemoryStore - Block broadcast_1992_piece0 stored as bytes in memory (estimated size 24.0 B, free 1915.0 MiB)
18:15:38.356 INFO  BlockManagerInfo - Added broadcast_1992_piece0 in memory on localhost:44275 (size: 24.0 B, free: 1918.9 MiB)
18:15:38.356 INFO  SparkContext - Created broadcast 1992 from broadcast at MarkDuplicatesSparkUtils.java:126
18:15:38.356 INFO  MemoryStore - Block broadcast_1993 stored as values in memory (estimated size 136.0 B, free 1915.0 MiB)
18:15:38.357 INFO  MemoryStore - Block broadcast_1993_piece0 stored as bytes in memory (estimated size 21.0 B, free 1915.0 MiB)
18:15:38.357 INFO  BlockManagerInfo - Added broadcast_1993_piece0 in memory on localhost:44275 (size: 21.0 B, free: 1918.9 MiB)
18:15:38.357 INFO  SparkContext - Created broadcast 1993 from broadcast at MarkDuplicatesSparkUtils.java:127
18:15:38.368 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:15:38.369 INFO  DAGScheduler - Registering RDD 5503 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 308
18:15:38.369 INFO  DAGScheduler - Registering RDD 5507 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 307
18:15:38.369 INFO  DAGScheduler - Registering RDD 5511 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 306
18:15:38.369 INFO  DAGScheduler - Got job 563 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:15:38.369 INFO  DAGScheduler - Final stage: ResultStage 1236 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:15:38.369 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1235)
18:15:38.369 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1235)
18:15:38.369 INFO  DAGScheduler - Submitting ShuffleMapStage 1233 (MapPartitionsRDD[5503] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:15:38.370 INFO  MemoryStore - Block broadcast_1994 stored as values in memory (estimated size 21.1 KiB, free 1914.9 MiB)
18:15:38.370 INFO  MemoryStore - Block broadcast_1994_piece0 stored as bytes in memory (estimated size 10.9 KiB, free 1914.9 MiB)
18:15:38.370 INFO  BlockManagerInfo - Added broadcast_1994_piece0 in memory on localhost:44275 (size: 10.9 KiB, free: 1918.9 MiB)
18:15:38.370 INFO  SparkContext - Created broadcast 1994 from broadcast at DAGScheduler.scala:1580
18:15:38.370 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1233 (MapPartitionsRDD[5503] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:15:38.370 INFO  TaskSchedulerImpl - Adding task set 1233.0 with 1 tasks resource profile 0
18:15:38.371 INFO  TaskSetManager - Starting task 0.0 in stage 1233.0 (TID 1072) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:15:38.371 INFO  Executor - Running task 0.0 in stage 1233.0 (TID 1072)
18:15:38.372 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.372 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.374 INFO  Executor - Finished task 0.0 in stage 1233.0 (TID 1072). 1922 bytes result sent to driver
18:15:38.374 INFO  TaskSetManager - Finished task 0.0 in stage 1233.0 (TID 1072) in 3 ms on localhost (executor driver) (1/1)
18:15:38.375 INFO  TaskSchedulerImpl - Removed TaskSet 1233.0, whose tasks have all completed, from pool 
18:15:38.375 INFO  DAGScheduler - ShuffleMapStage 1233 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.006 s
18:15:38.375 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.375 INFO  DAGScheduler - running: HashSet()
18:15:38.375 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1234, ShuffleMapStage 1235, ResultStage 1236)
18:15:38.375 INFO  DAGScheduler - failed: HashSet()
18:15:38.375 INFO  DAGScheduler - Submitting ShuffleMapStage 1234 (MapPartitionsRDD[5507] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:15:38.375 INFO  MemoryStore - Block broadcast_1995 stored as values in memory (estimated size 25.2 KiB, free 1914.9 MiB)
18:15:38.376 INFO  MemoryStore - Block broadcast_1995_piece0 stored as bytes in memory (estimated size 13.1 KiB, free 1914.9 MiB)
18:15:38.376 INFO  BlockManagerInfo - Added broadcast_1995_piece0 in memory on localhost:44275 (size: 13.1 KiB, free: 1918.8 MiB)
18:15:38.376 INFO  SparkContext - Created broadcast 1995 from broadcast at DAGScheduler.scala:1580
18:15:38.376 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1234 (MapPartitionsRDD[5507] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:15:38.376 INFO  TaskSchedulerImpl - Adding task set 1234.0 with 1 tasks resource profile 0
18:15:38.376 INFO  TaskSetManager - Starting task 0.0 in stage 1234.0 (TID 1073) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:15:38.377 INFO  Executor - Running task 0.0 in stage 1234.0 (TID 1073)
18:15:38.378 INFO  ShuffleBlockFetcherIterator - Getting 1 (106.0 B) non-empty blocks including 1 (106.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.378 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.381 INFO  Executor - Finished task 0.0 in stage 1234.0 (TID 1073). 1879 bytes result sent to driver
18:15:38.381 INFO  TaskSetManager - Finished task 0.0 in stage 1234.0 (TID 1073) in 5 ms on localhost (executor driver) (1/1)
18:15:38.381 INFO  TaskSchedulerImpl - Removed TaskSet 1234.0, whose tasks have all completed, from pool 
18:15:38.381 INFO  DAGScheduler - ShuffleMapStage 1234 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.006 s
18:15:38.381 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.381 INFO  DAGScheduler - running: HashSet()
18:15:38.381 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1235, ResultStage 1236)
18:15:38.381 INFO  DAGScheduler - failed: HashSet()
18:15:38.381 INFO  DAGScheduler - Submitting ShuffleMapStage 1235 (MapPartitionsRDD[5511] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:15:38.382 INFO  MemoryStore - Block broadcast_1996 stored as values in memory (estimated size 15.9 KiB, free 1914.9 MiB)
18:15:38.382 INFO  MemoryStore - Block broadcast_1996_piece0 stored as bytes in memory (estimated size 8.3 KiB, free 1914.9 MiB)
18:15:38.382 INFO  BlockManagerInfo - Added broadcast_1996_piece0 in memory on localhost:44275 (size: 8.3 KiB, free: 1918.8 MiB)
18:15:38.382 INFO  SparkContext - Created broadcast 1996 from broadcast at DAGScheduler.scala:1580
18:15:38.382 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1235 (MapPartitionsRDD[5511] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:15:38.382 INFO  TaskSchedulerImpl - Adding task set 1235.0 with 1 tasks resource profile 0
18:15:38.383 INFO  TaskSetManager - Starting task 0.0 in stage 1235.0 (TID 1074) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:38.383 INFO  Executor - Running task 0.0 in stage 1235.0 (TID 1074)
18:15:38.384 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.384 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.385 INFO  ShuffleBlockFetcherIterator - Getting 1 (60.0 B) non-empty blocks including 1 (60.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.385 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.386 INFO  Executor - Finished task 0.0 in stage 1235.0 (TID 1074). 1879 bytes result sent to driver
18:15:38.386 INFO  TaskSetManager - Finished task 0.0 in stage 1235.0 (TID 1074) in 3 ms on localhost (executor driver) (1/1)
18:15:38.386 INFO  TaskSchedulerImpl - Removed TaskSet 1235.0, whose tasks have all completed, from pool 
18:15:38.386 INFO  DAGScheduler - ShuffleMapStage 1235 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.005 s
18:15:38.386 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.386 INFO  DAGScheduler - running: HashSet()
18:15:38.386 INFO  DAGScheduler - waiting: HashSet(ResultStage 1236)
18:15:38.386 INFO  DAGScheduler - failed: HashSet()
18:15:38.387 INFO  DAGScheduler - Submitting ResultStage 1236 (MapPartitionsRDD[5513] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:15:38.387 INFO  MemoryStore - Block broadcast_1997 stored as values in memory (estimated size 17.1 KiB, free 1914.8 MiB)
18:15:38.387 INFO  MemoryStore - Block broadcast_1997_piece0 stored as bytes in memory (estimated size 9.0 KiB, free 1914.8 MiB)
18:15:38.387 INFO  BlockManagerInfo - Added broadcast_1997_piece0 in memory on localhost:44275 (size: 9.0 KiB, free: 1918.8 MiB)
18:15:38.388 INFO  SparkContext - Created broadcast 1997 from broadcast at DAGScheduler.scala:1580
18:15:38.388 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1236 (MapPartitionsRDD[5513] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:15:38.388 INFO  TaskSchedulerImpl - Adding task set 1236.0 with 1 tasks resource profile 0
18:15:38.388 INFO  TaskSetManager - Starting task 0.0 in stage 1236.0 (TID 1075) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.388 INFO  Executor - Running task 0.0 in stage 1236.0 (TID 1075)
18:15:38.390 INFO  ShuffleBlockFetcherIterator - Getting 1 (129.0 B) non-empty blocks including 1 (129.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.390 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.391 INFO  Executor - Finished task 0.0 in stage 1236.0 (TID 1075). 1930 bytes result sent to driver
18:15:38.391 INFO  TaskSetManager - Finished task 0.0 in stage 1236.0 (TID 1075) in 3 ms on localhost (executor driver) (1/1)
18:15:38.391 INFO  TaskSchedulerImpl - Removed TaskSet 1236.0, whose tasks have all completed, from pool 
18:15:38.391 INFO  DAGScheduler - ResultStage 1236 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.004 s
18:15:38.392 INFO  DAGScheduler - Job 563 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.392 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1236: Stage finished
18:15:38.392 INFO  DAGScheduler - Job 563 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.023394 s
18:15:38.401 INFO  MemoryStore - Block broadcast_1998 stored as values in memory (estimated size 5.6 KiB, free 1914.8 MiB)
18:15:38.402 INFO  MemoryStore - Block broadcast_1998_piece0 stored as bytes in memory (estimated size 500.0 B, free 1914.8 MiB)
18:15:38.402 INFO  BlockManagerInfo - Added broadcast_1998_piece0 in memory on localhost:44275 (size: 500.0 B, free: 1918.8 MiB)
18:15:38.402 INFO  SparkContext - Created broadcast 1998 from broadcast at ReadsSparkSink.java:133
18:15:38.405 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:15:38.405 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:38.405 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:38.421 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:15:38.421 INFO  DAGScheduler - Registering RDD 5515 (mapToPair at SparkUtils.java:161) as input to shuffle 309
18:15:38.422 INFO  DAGScheduler - Got job 564 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:15:38.422 INFO  DAGScheduler - Final stage: ResultStage 1241 (runJob at SparkHadoopWriter.scala:83)
18:15:38.422 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1240)
18:15:38.422 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1240)
18:15:38.422 INFO  DAGScheduler - Submitting ShuffleMapStage 1240 (MapPartitionsRDD[5515] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:38.422 INFO  MemoryStore - Block broadcast_1999 stored as values in memory (estimated size 15.0 KiB, free 1914.8 MiB)
18:15:38.423 INFO  MemoryStore - Block broadcast_1999_piece0 stored as bytes in memory (estimated size 7.8 KiB, free 1914.8 MiB)
18:15:38.423 INFO  BlockManagerInfo - Added broadcast_1999_piece0 in memory on localhost:44275 (size: 7.8 KiB, free: 1918.8 MiB)
18:15:38.423 INFO  SparkContext - Created broadcast 1999 from broadcast at DAGScheduler.scala:1580
18:15:38.423 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1240 (MapPartitionsRDD[5515] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:38.423 INFO  TaskSchedulerImpl - Adding task set 1240.0 with 1 tasks resource profile 0
18:15:38.423 INFO  TaskSetManager - Starting task 0.0 in stage 1240.0 (TID 1076) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:38.424 INFO  Executor - Running task 0.0 in stage 1240.0 (TID 1076)
18:15:38.425 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.425 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.426 INFO  ShuffleBlockFetcherIterator - Getting 1 (60.0 B) non-empty blocks including 1 (60.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.426 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.427 INFO  Executor - Finished task 0.0 in stage 1240.0 (TID 1076). 1879 bytes result sent to driver
18:15:38.427 INFO  TaskSetManager - Finished task 0.0 in stage 1240.0 (TID 1076) in 4 ms on localhost (executor driver) (1/1)
18:15:38.427 INFO  TaskSchedulerImpl - Removed TaskSet 1240.0, whose tasks have all completed, from pool 
18:15:38.427 INFO  DAGScheduler - ShuffleMapStage 1240 (mapToPair at SparkUtils.java:161) finished in 0.005 s
18:15:38.427 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.427 INFO  DAGScheduler - running: HashSet()
18:15:38.427 INFO  DAGScheduler - waiting: HashSet(ResultStage 1241)
18:15:38.427 INFO  DAGScheduler - failed: HashSet()
18:15:38.427 INFO  DAGScheduler - Submitting ResultStage 1241 (MapPartitionsRDD[5521] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:15:38.435 INFO  MemoryStore - Block broadcast_2000 stored as values in memory (estimated size 160.3 KiB, free 1914.7 MiB)
18:15:38.436 INFO  MemoryStore - Block broadcast_2000_piece0 stored as bytes in memory (estimated size 72.1 KiB, free 1914.6 MiB)
18:15:38.436 INFO  BlockManagerInfo - Added broadcast_2000_piece0 in memory on localhost:44275 (size: 72.1 KiB, free: 1918.7 MiB)
18:15:38.436 INFO  SparkContext - Created broadcast 2000 from broadcast at DAGScheduler.scala:1580
18:15:38.436 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1241 (MapPartitionsRDD[5521] at saveAsTextFile at SamSink.java:65) (first 15 tasks are for partitions Vector(0))
18:15:38.436 INFO  TaskSchedulerImpl - Adding task set 1241.0 with 1 tasks resource profile 0
18:15:38.436 INFO  TaskSetManager - Starting task 0.0 in stage 1241.0 (TID 1077) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.436 INFO  Executor - Running task 0.0 in stage 1241.0 (TID 1077)
18:15:38.439 INFO  ShuffleBlockFetcherIterator - Getting 1 (490.0 B) non-empty blocks including 1 (490.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.440 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.441 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:15:38.441 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:38.441 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:38.452 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271815381663972298590827071_5521_m_000000_0' to file:/tmp/MarkDups12238914450616315778/MarkDups.sam.parts/_temporary/0/task_202505271815381663972298590827071_5521_m_000000
18:15:38.452 INFO  SparkHadoopMapRedUtil - attempt_202505271815381663972298590827071_5521_m_000000_0: Committed. Elapsed time: 0 ms.
18:15:38.452 INFO  Executor - Finished task 0.0 in stage 1241.0 (TID 1077). 1858 bytes result sent to driver
18:15:38.452 INFO  TaskSetManager - Finished task 0.0 in stage 1241.0 (TID 1077) in 16 ms on localhost (executor driver) (1/1)
18:15:38.453 INFO  TaskSchedulerImpl - Removed TaskSet 1241.0, whose tasks have all completed, from pool 
18:15:38.453 INFO  DAGScheduler - ResultStage 1241 (runJob at SparkHadoopWriter.scala:83) finished in 0.025 s
18:15:38.453 INFO  DAGScheduler - Job 564 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.453 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1241: Stage finished
18:15:38.453 INFO  DAGScheduler - Job 564 finished: runJob at SparkHadoopWriter.scala:83, took 0.031688 s
18:15:38.453 INFO  SparkHadoopWriter - Start to commit write Job job_202505271815381663972298590827071_5521.
18:15:38.457 INFO  SparkHadoopWriter - Write Job job_202505271815381663972298590827071_5521 committed. Elapsed time: 4 ms.
18:15:38.464 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups12238914450616315778/MarkDups.sam
18:15:38.468 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups12238914450616315778/MarkDups.sam done
18:15:38.468 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:15:38 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
18:15:38.475 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:38.475 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:15:38.475 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:15:38.475 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:15:38.475 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:15:38.475 INFO  MarkDuplicatesSpark - Start Date/Time: May 27, 2025 at 6:15:38 PM UTC
18:15:38.475 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:38.475 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:15:38.475 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:15:38.475 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:15:38.475 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:15:38.475 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:15:38.475 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:15:38.475 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:15:38.475 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:15:38.475 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:15:38.475 INFO  MarkDuplicatesSpark - Initializing engine
18:15:38.475 INFO  MarkDuplicatesSpark - Done initializing engine
18:15:38.475 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:15:38.478 INFO  MemoryStore - Block broadcast_2001 stored as values in memory (estimated size 306.3 KiB, free 1914.3 MiB)
18:15:38.488 INFO  MemoryStore - Block broadcast_2001_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1914.2 MiB)
18:15:38.488 INFO  BlockManagerInfo - Added broadcast_2001_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1918.7 MiB)
18:15:38.488 INFO  SparkContext - Created broadcast 2001 from newAPIHadoopFile at PathSplitSource.java:96
18:15:38.508 INFO  MemoryStore - Block broadcast_2002 stored as values in memory (estimated size 306.3 KiB, free 1913.9 MiB)
18:15:38.514 INFO  MemoryStore - Block broadcast_2002_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1913.9 MiB)
18:15:38.514 INFO  BlockManagerInfo - Added broadcast_2002_piece0 in memory on localhost:44275 (size: 64.4 KiB, free: 1918.6 MiB)
18:15:38.515 INFO  SparkContext - Created broadcast 2002 from newAPIHadoopFile at PathSplitSource.java:96
18:15:38.547 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:15:38.547 INFO  FileInputFormat - Total input files to process : 1
18:15:38.548 INFO  DAGScheduler - Registering RDD 5535 (mapToPair at SparkUtils.java:161) as input to shuffle 310
18:15:38.548 INFO  DAGScheduler - Got job 565 (collect at SparkUtils.java:205) with 1 output partitions
18:15:38.548 INFO  DAGScheduler - Final stage: ResultStage 1243 (collect at SparkUtils.java:205)
18:15:38.548 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1242)
18:15:38.548 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1242)
18:15:38.548 INFO  DAGScheduler - Submitting ShuffleMapStage 1242 (MapPartitionsRDD[5535] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:38.564 INFO  MemoryStore - Block broadcast_2003 stored as values in memory (estimated size 481.4 KiB, free 1913.4 MiB)
18:15:38.567 INFO  MemoryStore - Block broadcast_2003_piece0 stored as bytes in memory (estimated size 207.4 KiB, free 1913.2 MiB)
18:15:38.567 INFO  BlockManagerInfo - Added broadcast_2003_piece0 in memory on localhost:44275 (size: 207.4 KiB, free: 1918.4 MiB)
18:15:38.567 INFO  SparkContext - Created broadcast 2003 from broadcast at DAGScheduler.scala:1580
18:15:38.567 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1242 (MapPartitionsRDD[5535] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:38.567 INFO  TaskSchedulerImpl - Adding task set 1242.0 with 1 tasks resource profile 0
18:15:38.568 INFO  TaskSetManager - Starting task 0.0 in stage 1242.0 (TID 1078) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9757 bytes) 
18:15:38.568 INFO  Executor - Running task 0.0 in stage 1242.0 (TID 1078)
18:15:38.596 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/inputSingleLibrarySolexa16404.bam:0+5416
18:15:38.601 INFO  Executor - Finished task 0.0 in stage 1242.0 (TID 1078). 1148 bytes result sent to driver
18:15:38.601 INFO  TaskSetManager - Finished task 0.0 in stage 1242.0 (TID 1078) in 34 ms on localhost (executor driver) (1/1)
18:15:38.601 INFO  TaskSchedulerImpl - Removed TaskSet 1242.0, whose tasks have all completed, from pool 
18:15:38.601 INFO  DAGScheduler - ShuffleMapStage 1242 (mapToPair at SparkUtils.java:161) finished in 0.053 s
18:15:38.601 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.601 INFO  DAGScheduler - running: HashSet()
18:15:38.601 INFO  DAGScheduler - waiting: HashSet(ResultStage 1243)
18:15:38.601 INFO  DAGScheduler - failed: HashSet()
18:15:38.601 INFO  DAGScheduler - Submitting ResultStage 1243 (MapPartitionsRDD[5538] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:15:38.601 INFO  MemoryStore - Block broadcast_2004 stored as values in memory (estimated size 7.4 KiB, free 1913.2 MiB)
18:15:38.602 INFO  MemoryStore - Block broadcast_2004_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1913.2 MiB)
18:15:38.602 INFO  BlockManagerInfo - Added broadcast_2004_piece0 in memory on localhost:44275 (size: 4.1 KiB, free: 1918.4 MiB)
18:15:38.602 INFO  SparkContext - Created broadcast 2004 from broadcast at DAGScheduler.scala:1580
18:15:38.602 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1243 (MapPartitionsRDD[5538] at mapPartitions at SparkUtils.java:188) (first 15 tasks are for partitions Vector(0))
18:15:38.602 INFO  TaskSchedulerImpl - Adding task set 1243.0 with 1 tasks resource profile 0
18:15:38.602 INFO  TaskSetManager - Starting task 0.0 in stage 1243.0 (TID 1079) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.603 INFO  Executor - Running task 0.0 in stage 1243.0 (TID 1079)
18:15:38.603 INFO  ShuffleBlockFetcherIterator - Getting 1 (4.3 KiB) non-empty blocks including 1 (4.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.603 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.605 INFO  Executor - Finished task 0.0 in stage 1243.0 (TID 1079). 2039 bytes result sent to driver
18:15:38.605 INFO  TaskSetManager - Finished task 0.0 in stage 1243.0 (TID 1079) in 3 ms on localhost (executor driver) (1/1)
18:15:38.605 INFO  TaskSchedulerImpl - Removed TaskSet 1243.0, whose tasks have all completed, from pool 
18:15:38.605 INFO  DAGScheduler - ResultStage 1243 (collect at SparkUtils.java:205) finished in 0.004 s
18:15:38.605 INFO  DAGScheduler - Job 565 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.605 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1243: Stage finished
18:15:38.605 INFO  DAGScheduler - Job 565 finished: collect at SparkUtils.java:205, took 0.058281 s
18:15:38.609 INFO  MemoryStore - Block broadcast_2005 stored as values in memory (estimated size 392.0 B, free 1913.2 MiB)
18:15:38.610 INFO  MemoryStore - Block broadcast_2005_piece0 stored as bytes in memory (estimated size 33.0 B, free 1913.2 MiB)
18:15:38.610 INFO  BlockManagerInfo - Added broadcast_2005_piece0 in memory on localhost:44275 (size: 33.0 B, free: 1918.4 MiB)
18:15:38.610 INFO  SparkContext - Created broadcast 2005 from broadcast at MarkDuplicatesSparkUtils.java:126
18:15:38.610 INFO  MemoryStore - Block broadcast_2006 stored as values in memory (estimated size 144.0 B, free 1913.2 MiB)
18:15:38.610 INFO  MemoryStore - Block broadcast_2006_piece0 stored as bytes in memory (estimated size 28.0 B, free 1913.2 MiB)
18:15:38.610 INFO  BlockManagerInfo - Added broadcast_2006_piece0 in memory on localhost:44275 (size: 28.0 B, free: 1918.4 MiB)
18:15:38.611 INFO  SparkContext - Created broadcast 2006 from broadcast at MarkDuplicatesSparkUtils.java:127
18:15:38.623 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:15:38.623 INFO  DAGScheduler - Registering RDD 5547 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 313
18:15:38.623 INFO  DAGScheduler - Registering RDD 5551 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 312
18:15:38.623 INFO  DAGScheduler - Registering RDD 5555 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 311
18:15:38.623 INFO  DAGScheduler - Got job 566 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:15:38.623 INFO  DAGScheduler - Final stage: ResultStage 1248 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:15:38.624 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1247)
18:15:38.624 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1247)
18:15:38.624 INFO  DAGScheduler - Submitting ShuffleMapStage 1245 (MapPartitionsRDD[5547] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:15:38.624 INFO  MemoryStore - Block broadcast_2007 stored as values in memory (estimated size 45.2 KiB, free 1913.1 MiB)
18:15:38.625 INFO  MemoryStore - Block broadcast_2007_piece0 stored as bytes in memory (estimated size 17.1 KiB, free 1913.1 MiB)
18:15:38.625 INFO  BlockManagerInfo - Added broadcast_2007_piece0 in memory on localhost:44275 (size: 17.1 KiB, free: 1918.4 MiB)
18:15:38.625 INFO  SparkContext - Created broadcast 2007 from broadcast at DAGScheduler.scala:1580
18:15:38.625 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1245 (MapPartitionsRDD[5547] at flatMapToPair at MarkDuplicatesSparkUtils.java:130) (first 15 tasks are for partitions Vector(0))
18:15:38.625 INFO  TaskSchedulerImpl - Adding task set 1245.0 with 1 tasks resource profile 0
18:15:38.625 INFO  TaskSetManager - Starting task 0.0 in stage 1245.0 (TID 1080) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:15:38.626 INFO  Executor - Running task 0.0 in stage 1245.0 (TID 1080)
18:15:38.627 INFO  ShuffleBlockFetcherIterator - Getting 1 (4.3 KiB) non-empty blocks including 1 (4.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.627 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.629 INFO  Executor - Finished task 0.0 in stage 1245.0 (TID 1080). 1922 bytes result sent to driver
18:15:38.629 INFO  TaskSetManager - Finished task 0.0 in stage 1245.0 (TID 1080) in 4 ms on localhost (executor driver) (1/1)
18:15:38.629 INFO  TaskSchedulerImpl - Removed TaskSet 1245.0, whose tasks have all completed, from pool 
18:15:38.630 INFO  DAGScheduler - ShuffleMapStage 1245 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.006 s
18:15:38.630 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.630 INFO  DAGScheduler - running: HashSet()
18:15:38.630 INFO  DAGScheduler - waiting: HashSet(ResultStage 1248, ShuffleMapStage 1246, ShuffleMapStage 1247)
18:15:38.630 INFO  DAGScheduler - failed: HashSet()
18:15:38.630 INFO  DAGScheduler - Submitting ShuffleMapStage 1246 (MapPartitionsRDD[5551] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:15:38.630 INFO  MemoryStore - Block broadcast_2008 stored as values in memory (estimated size 49.3 KiB, free 1913.1 MiB)
18:15:38.631 INFO  MemoryStore - Block broadcast_2008_piece0 stored as bytes in memory (estimated size 19.3 KiB, free 1913.0 MiB)
18:15:38.631 INFO  BlockManagerInfo - Added broadcast_2008_piece0 in memory on localhost:44275 (size: 19.3 KiB, free: 1918.4 MiB)
18:15:38.631 INFO  SparkContext - Created broadcast 2008 from broadcast at DAGScheduler.scala:1580
18:15:38.631 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1246 (MapPartitionsRDD[5551] at mapToPair at MarkDuplicatesSpark.java:217) (first 15 tasks are for partitions Vector(0))
18:15:38.631 INFO  TaskSchedulerImpl - Adding task set 1246.0 with 1 tasks resource profile 0
18:15:38.631 INFO  TaskSetManager - Starting task 0.0 in stage 1246.0 (TID 1081) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:15:38.632 INFO  Executor - Running task 0.0 in stage 1246.0 (TID 1081)
18:15:38.633 INFO  ShuffleBlockFetcherIterator - Getting 1 (593.0 B) non-empty blocks including 1 (593.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.633 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.637 INFO  Executor - Finished task 0.0 in stage 1246.0 (TID 1081). 1922 bytes result sent to driver
18:15:38.637 INFO  TaskSetManager - Finished task 0.0 in stage 1246.0 (TID 1081) in 6 ms on localhost (executor driver) (1/1)
18:15:38.637 INFO  TaskSchedulerImpl - Removed TaskSet 1246.0, whose tasks have all completed, from pool 
18:15:38.637 INFO  DAGScheduler - ShuffleMapStage 1246 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.007 s
18:15:38.637 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.637 INFO  DAGScheduler - running: HashSet()
18:15:38.637 INFO  DAGScheduler - waiting: HashSet(ResultStage 1248, ShuffleMapStage 1247)
18:15:38.637 INFO  DAGScheduler - failed: HashSet()
18:15:38.638 INFO  DAGScheduler - Submitting ShuffleMapStage 1247 (MapPartitionsRDD[5555] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:15:38.638 INFO  MemoryStore - Block broadcast_2009 stored as values in memory (estimated size 40.0 KiB, free 1913.0 MiB)
18:15:38.639 INFO  MemoryStore - Block broadcast_2009_piece0 stored as bytes in memory (estimated size 14.5 KiB, free 1913.0 MiB)
18:15:38.639 INFO  BlockManagerInfo - Added broadcast_2009_piece0 in memory on localhost:44275 (size: 14.5 KiB, free: 1918.4 MiB)
18:15:38.639 INFO  SparkContext - Created broadcast 2009 from broadcast at DAGScheduler.scala:1580
18:15:38.639 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1247 (MapPartitionsRDD[5555] at mapToPair at MarkDuplicatesSparkUtils.java:497) (first 15 tasks are for partitions Vector(0))
18:15:38.639 INFO  TaskSchedulerImpl - Adding task set 1247.0 with 1 tasks resource profile 0
18:15:38.639 INFO  TaskSetManager - Starting task 0.0 in stage 1247.0 (TID 1082) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:38.639 INFO  Executor - Running task 0.0 in stage 1247.0 (TID 1082)
18:15:38.640 INFO  ShuffleBlockFetcherIterator - Getting 1 (4.3 KiB) non-empty blocks including 1 (4.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.640 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.642 INFO  ShuffleBlockFetcherIterator - Getting 1 (652.0 B) non-empty blocks including 1 (652.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.642 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.643 INFO  Executor - Finished task 0.0 in stage 1247.0 (TID 1082). 1879 bytes result sent to driver
18:15:38.643 INFO  TaskSetManager - Finished task 0.0 in stage 1247.0 (TID 1082) in 4 ms on localhost (executor driver) (1/1)
18:15:38.643 INFO  TaskSchedulerImpl - Removed TaskSet 1247.0, whose tasks have all completed, from pool 
18:15:38.643 INFO  DAGScheduler - ShuffleMapStage 1247 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.005 s
18:15:38.643 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.643 INFO  DAGScheduler - running: HashSet()
18:15:38.643 INFO  DAGScheduler - waiting: HashSet(ResultStage 1248)
18:15:38.643 INFO  DAGScheduler - failed: HashSet()
18:15:38.643 INFO  DAGScheduler - Submitting ResultStage 1248 (MapPartitionsRDD[5557] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:15:38.644 INFO  MemoryStore - Block broadcast_2010 stored as values in memory (estimated size 41.2 KiB, free 1913.0 MiB)
18:15:38.644 INFO  MemoryStore - Block broadcast_2010_piece0 stored as bytes in memory (estimated size 15.3 KiB, free 1912.9 MiB)
18:15:38.644 INFO  BlockManagerInfo - Added broadcast_2010_piece0 in memory on localhost:44275 (size: 15.3 KiB, free: 1918.4 MiB)
18:15:38.644 INFO  SparkContext - Created broadcast 2010 from broadcast at DAGScheduler.scala:1580
18:15:38.644 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1248 (MapPartitionsRDD[5557] at mapValues at MarkDuplicatesSparkUtils.java:519) (first 15 tasks are for partitions Vector(0))
18:15:38.644 INFO  TaskSchedulerImpl - Adding task set 1248.0 with 1 tasks resource profile 0
18:15:38.645 INFO  TaskSetManager - Starting task 0.0 in stage 1248.0 (TID 1083) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.645 INFO  Executor - Running task 0.0 in stage 1248.0 (TID 1083)
18:15:38.646 INFO  ShuffleBlockFetcherIterator - Getting 1 (142.0 B) non-empty blocks including 1 (142.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.646 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.647 INFO  Executor - Finished task 0.0 in stage 1248.0 (TID 1083). 1901 bytes result sent to driver
18:15:38.647 INFO  TaskSetManager - Finished task 0.0 in stage 1248.0 (TID 1083) in 3 ms on localhost (executor driver) (1/1)
18:15:38.647 INFO  TaskSchedulerImpl - Removed TaskSet 1248.0, whose tasks have all completed, from pool 
18:15:38.647 INFO  DAGScheduler - ResultStage 1248 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.004 s
18:15:38.647 INFO  DAGScheduler - Job 566 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.647 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1248: Stage finished
18:15:38.647 INFO  DAGScheduler - Job 566 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.024579 s
18:15:38.658 INFO  MemoryStore - Block broadcast_2011 stored as values in memory (estimated size 93.5 KiB, free 1912.8 MiB)
18:15:38.659 INFO  MemoryStore - Block broadcast_2011_piece0 stored as bytes in memory (estimated size 5.6 KiB, free 1912.8 MiB)
18:15:38.659 INFO  BlockManagerInfo - Added broadcast_2011_piece0 in memory on localhost:44275 (size: 5.6 KiB, free: 1918.3 MiB)
18:15:38.659 INFO  SparkContext - Created broadcast 2011 from broadcast at ReadsSparkSink.java:133
18:15:38.662 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:15:38.662 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:38.662 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:38.678 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:15:38.678 INFO  DAGScheduler - Registering RDD 5559 (mapToPair at SparkUtils.java:161) as input to shuffle 314
18:15:38.678 INFO  DAGScheduler - Got job 567 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:15:38.678 INFO  DAGScheduler - Final stage: ResultStage 1253 (runJob at SparkHadoopWriter.scala:83)
18:15:38.678 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1252)
18:15:38.678 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1252)
18:15:38.679 INFO  DAGScheduler - Submitting ShuffleMapStage 1252 (MapPartitionsRDD[5559] at mapToPair at SparkUtils.java:161), which has no missing parents
18:15:38.679 INFO  MemoryStore - Block broadcast_2012 stored as values in memory (estimated size 39.1 KiB, free 1912.8 MiB)
18:15:38.680 INFO  MemoryStore - Block broadcast_2012_piece0 stored as bytes in memory (estimated size 14.1 KiB, free 1912.8 MiB)
18:15:38.680 INFO  BlockManagerInfo - Added broadcast_2012_piece0 in memory on localhost:44275 (size: 14.1 KiB, free: 1918.3 MiB)
18:15:38.680 INFO  SparkContext - Created broadcast 2012 from broadcast at DAGScheduler.scala:1580
18:15:38.680 INFO  DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 1252 (MapPartitionsRDD[5559] at mapToPair at SparkUtils.java:161) (first 15 tasks are for partitions Vector(0))
18:15:38.680 INFO  TaskSchedulerImpl - Adding task set 1252.0 with 1 tasks resource profile 0
18:15:38.680 INFO  TaskSetManager - Starting task 0.0 in stage 1252.0 (TID 1084) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:15:38.680 INFO  Executor - Running task 0.0 in stage 1252.0 (TID 1084)
18:15:38.682 INFO  ShuffleBlockFetcherIterator - Getting 1 (4.3 KiB) non-empty blocks including 1 (4.3 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.682 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.683 INFO  ShuffleBlockFetcherIterator - Getting 1 (652.0 B) non-empty blocks including 1 (652.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.683 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.684 INFO  Executor - Finished task 0.0 in stage 1252.0 (TID 1084). 1922 bytes result sent to driver
18:15:38.684 INFO  TaskSetManager - Finished task 0.0 in stage 1252.0 (TID 1084) in 4 ms on localhost (executor driver) (1/1)
18:15:38.684 INFO  TaskSchedulerImpl - Removed TaskSet 1252.0, whose tasks have all completed, from pool 
18:15:38.684 INFO  DAGScheduler - ShuffleMapStage 1252 (mapToPair at SparkUtils.java:161) finished in 0.005 s
18:15:38.684 INFO  DAGScheduler - looking for newly runnable stages
18:15:38.684 INFO  DAGScheduler - running: HashSet()
18:15:38.684 INFO  DAGScheduler - waiting: HashSet(ResultStage 1253)
18:15:38.684 INFO  DAGScheduler - failed: HashSet()
18:15:38.684 INFO  DAGScheduler - Submitting ResultStage 1253 (MapPartitionsRDD[5565] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:15:38.691 INFO  MemoryStore - Block broadcast_2013 stored as values in memory (estimated size 184.3 KiB, free 1912.6 MiB)
18:15:38.692 INFO  MemoryStore - Block broadcast_2013_piece0 stored as bytes in memory (estimated size 78.3 KiB, free 1912.5 MiB)
18:15:38.692 INFO  BlockManagerInfo - Added broadcast_2013_piece0 in memory on localhost:44275 (size: 78.3 KiB, free: 1918.3 MiB)
18:15:38.692 INFO  SparkContext - Created broadcast 2013 from broadcast at DAGScheduler.scala:1580
18:15:38.692 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 1253 (MapPartitionsRDD[5565] at saveAsTextFile at SamSink.java:65) (first 15 tasks are for partitions Vector(0))
18:15:38.692 INFO  TaskSchedulerImpl - Adding task set 1253.0 with 1 tasks resource profile 0
18:15:38.692 INFO  TaskSetManager - Starting task 0.0 in stage 1253.0 (TID 1085) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:15:38.693 INFO  Executor - Running task 0.0 in stage 1253.0 (TID 1085)
18:15:38.696 INFO  ShuffleBlockFetcherIterator - Getting 1 (3.9 KiB) non-empty blocks including 1 (3.9 KiB) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
18:15:38.696 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:15:38.697 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:15:38.697 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:15:38.697 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:15:38.707 INFO  FileOutputCommitter - Saved output of task 'attempt_202505271815388634725100754344105_5565_m_000000_0' to file:/tmp/MarkDups13202729626399809347/MarkDups.sam.parts/_temporary/0/task_202505271815388634725100754344105_5565_m_000000
18:15:38.707 INFO  SparkHadoopMapRedUtil - attempt_202505271815388634725100754344105_5565_m_000000_0: Committed. Elapsed time: 0 ms.
18:15:38.708 INFO  Executor - Finished task 0.0 in stage 1253.0 (TID 1085). 1858 bytes result sent to driver
18:15:38.708 INFO  TaskSetManager - Finished task 0.0 in stage 1253.0 (TID 1085) in 16 ms on localhost (executor driver) (1/1)
18:15:38.708 INFO  TaskSchedulerImpl - Removed TaskSet 1253.0, whose tasks have all completed, from pool 
18:15:38.708 INFO  DAGScheduler - ResultStage 1253 (runJob at SparkHadoopWriter.scala:83) finished in 0.023 s
18:15:38.708 INFO  DAGScheduler - Job 567 is finished. Cancelling potential speculative or zombie tasks for this job
18:15:38.708 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1253: Stage finished
18:15:38.708 INFO  DAGScheduler - Job 567 finished: runJob at SparkHadoopWriter.scala:83, took 0.030133 s
18:15:38.708 INFO  SparkHadoopWriter - Start to commit write Job job_202505271815388634725100754344105_5565.
18:15:38.712 INFO  SparkHadoopWriter - Write Job job_202505271815388634725100754344105_5565 committed. Elapsed time: 4 ms.
18:15:38.719 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups13202729626399809347/MarkDups.sam
18:15:38.723 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups13202729626399809347/MarkDups.sam done
18:15:38.723 INFO  MarkDuplicatesSpark - Shutting down engine
[May 27, 2025 at 6:15:38 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:39 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:39 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:39 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:39 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:40 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:40 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:40 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:41 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:41 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:41 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:42 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:42 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:42 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:42 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:43 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:43 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:43 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:44 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
18:15:44.276 ERROR Executor - Exception in task 0.0 in stage 1473.0 (TID 1232)
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) ~[main/:?]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.EmptyFragment.<init>(EmptyFragment.java:36) ~[main/:?]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.MarkDuplicatesSparkRecord.newEmptyFragment(MarkDuplicatesSparkRecord.java:44) ~[main/:?]
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.lambda$transformToDuplicateNames$0(MarkDuplicatesSparkUtils.java:141) ~[main/:?]
	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) ~[main/:?]
	at org.apache.spark.api.java.JavaRDDLike.$anonfun$flatMapToPair$1(JavaRDDLike.scala:143) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at scala.collection.Iterator$$anon$10.nextCur(Iterator.scala:594) ~[scala-library-2.13.14.jar:?]
	at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:608) ~[scala-library-2.13.14.jar:?]
	at org.apache.spark.shuffle.sort.BypassMergeSortShuffleWriter.write(BypassMergeSortShuffleWriter.java:140) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.shuffle.ShuffleWriteProcessor.write(ShuffleWriteProcessor.scala:59) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:104) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:54) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.TaskContext.runTaskWithListeners(TaskContext.scala:161) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.scheduler.Task.run(Task.scala:141) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.executor.Executor$TaskRunner.$anonfun$run$4(Executor.scala:620) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally(SparkErrorUtils.scala:64) ~[spark-common-utils_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally$(SparkErrorUtils.scala:61) ~[spark-common-utils_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.util.Utils$.tryWithSafeFinally(Utils.scala:94) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:623) [spark-core_2.13-3.5.0.jar:3.5.0]
	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:833) [?:?]
18:15:44.292 ERROR TaskSetManager - Task 0 in stage 1473.0 failed 1 times; aborting job
[May 27, 2025 at 6:15:44 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
18:15:44.507 ERROR Executor - Exception in task 0.0 in stage 1480.0 (TID 1235)
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) ~[main/:?]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.EmptyFragment.<init>(EmptyFragment.java:36) ~[main/:?]
	at org.broadinstitute.hellbender.utils.read.markduplicates.sparkrecords.MarkDuplicatesSparkRecord.newEmptyFragment(MarkDuplicatesSparkRecord.java:44) ~[main/:?]
	at org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSparkUtils.lambda$transformToDuplicateNames$0(MarkDuplicatesSparkUtils.java:141) ~[main/:?]
	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) ~[main/:?]
	at org.apache.spark.api.java.JavaRDDLike.$anonfun$flatMapToPair$1(JavaRDDLike.scala:143) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at scala.collection.Iterator$$anon$10.nextCur(Iterator.scala:594) ~[scala-library-2.13.14.jar:?]
	at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:608) ~[scala-library-2.13.14.jar:?]
	at org.apache.spark.shuffle.sort.BypassMergeSortShuffleWriter.write(BypassMergeSortShuffleWriter.java:140) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.shuffle.ShuffleWriteProcessor.write(ShuffleWriteProcessor.scala:59) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:104) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:54) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.TaskContext.runTaskWithListeners(TaskContext.scala:161) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.scheduler.Task.run(Task.scala:141) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.executor.Executor$TaskRunner.$anonfun$run$4(Executor.scala:620) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally(SparkErrorUtils.scala:64) ~[spark-common-utils_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.util.SparkErrorUtils.tryWithSafeFinally$(SparkErrorUtils.scala:61) ~[spark-common-utils_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.util.Utils$.tryWithSafeFinally(Utils.scala:94) ~[spark-core_2.13-3.5.0.jar:3.5.0]
	at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:623) [spark-core_2.13-3.5.0.jar:3.5.0]
	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:833) [?:?]
18:15:44.509 ERROR TaskSetManager - Task 0 in stage 1480.0 failed 1 times; aborting job
[May 27, 2025 at 6:15:44 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:44 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:45 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:45 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:45 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:46 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:46 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:46 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:46 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:47 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:47 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:47 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:48 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:48 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:48 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:48 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:49 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:49 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:49 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:50 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:50 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:50 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:51 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:51 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:51 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:51 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:52 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:52 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:52 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:53 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:53 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:53 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:53 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:54 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:54 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:54 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:55 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:55 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:55 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:56 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:56 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:56 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:56 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:57 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:57 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:57 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:58 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:58 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:58 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:59 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:59 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:59 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:15:59 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:00 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:00 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:00 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:01 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:01 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:01 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:01 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:02 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:02 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:02 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:03 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:03 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:03 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:04 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:04 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:04 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:04 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:05 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:05 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:05 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:06 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:06 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:06 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:06 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:07 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:07 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:07 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:08 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816
[May 27, 2025 at 6:16:08 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1432354816