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

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

tests
0

failures
0

ignored
1m1.19s

duration
100%

successful

Tests

Test Duration Result
assertThatExpectedOutputUpdateToggleIsDisabled 0s passed
testAssertAssumeUnsortedFilesAreQueryGroupedFiles 0.591s passed
testAssertCorrectSortOrderMultipleBams 0.127s passed
testAssertCorrectSortOrderMultipleBamsOverriding 0.493s passed
testBulkFragmentsNoDuplicates 0.928s passed
testBulkFragmentsWithDuplicates 2.056s passed
testDifferentChromosomesInOppositeOrder 0.299s 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.301s 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.252s 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.259s passed
testFlowModeFlag 1.652s passed
testHashCollisionHandling 1.045s 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.310s 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.308s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[0](true, true, true) 0.311s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[1](true, false, true) 0.312s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[2](false, true, true) 0.298s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[3](true, true, false) 0.311s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[4](true, false, false) 0.299s passed
testManyOpticalDuplicateClusterOneEndSamePositionOneCluster[5](false, true, false) 0.307s passed
testMappedFragmentAndMappedPairFirstOfPairNonPrimary 0.320s passed
testMappedFragmentAndMatePairFirstUnmapped 0.301s passed
testMappedFragmentAndMatePairSecondUnmapped 0.321s passed
testMappedPairAndMappedFragmentAndMatePairFirstUnmapped 0.299s passed
testMappedPairAndMappedFragmentAndMatePairSecondUnmapped 0.343s passed
testMappedPairAndMatePairFirstOppositeStrandSecondUnmapped 0.303s passed
testMappedPairAndMatePairFirstUnmapped 0.290s passed
testMappedPairAndMatePairSecondUnmapped 0.319s passed
testMappedPairWithFirstEndSamePositionAndOther 0.299s passed
testMappedPairWithSamePosition 0.300s passed
testMappedPairWithSamePositionSameCigar 0.294s passed
testMarkDuplicatesSparkDeletingDuplicateReads[0]([Ljava.io.File;@2d5b2b11, 20, 0, {Solexa-16419=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16416=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16404=[0, 3, 0, 0, 0, 0, 0.0, 0], Solexa-16406=[0, 1, 0, 0, 0, 0, 0.0, 0], Solexa-16412=[0, 1, 0, 0, 0, 0, 0.0, 0]}) 0.376s passed
testMarkDuplicatesSparkDeletingDuplicateReads[1]([Ljava.io.File;@28481132, 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.386s passed
testMarkDuplicatesSparkDeletingDuplicateReads[2]([Ljava.io.File;@600a98dd, 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.394s passed
testMarkDuplicatesSparkDeletingDuplicateReads[3]([Ljava.io.File;@4ac6311f, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.351s passed
testMarkDuplicatesSparkDeletingDuplicateReads[4]([Ljava.io.File;@30a1793d, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.325s passed
testMarkDuplicatesSparkDeletingDuplicateReads[5]([Ljava.io.File;@299ad006, 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.278s passed
testMarkDuplicatesSparkDeletingDuplicateReads[6]([Ljava.io.File;@65fd7d82, 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.233s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[0]([Ljava.io.File;@95c6144, 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.377s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[1]([Ljava.io.File;@49433262, 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.426s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[2]([Ljava.io.File;@3e2ec392, 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.369s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[3]([Ljava.io.File;@745def43, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.329s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[4]([Ljava.io.File;@2d0a00cb, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.329s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[5]([Ljava.io.File;@571c18e4, 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.237s passed
testMarkDuplicatesSparkDeletingOpticalDuplicateReads[6]([Ljava.io.File;@6898cfd, 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.241s passed
testMarkDuplicatesSparkIntegrationTestLocal[0]([Ljava.io.File;@1f41eced, 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.340s passed
testMarkDuplicatesSparkIntegrationTestLocal[1]([Ljava.io.File;@358599cd, 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.363s passed
testMarkDuplicatesSparkIntegrationTestLocal[2]([Ljava.io.File;@1e3e9127, 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[3]([Ljava.io.File;@3fb1813b, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.330s passed
testMarkDuplicatesSparkIntegrationTestLocal[4]([Ljava.io.File;@7e97fdc6, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.358s passed
testMarkDuplicatesSparkIntegrationTestLocal[5]([Ljava.io.File;@6d679471, 94, 8, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0], Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 1.197s passed
testMarkDuplicatesSparkIntegrationTestLocal[6]([Ljava.io.File;@7498b069, 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.250s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[0]([Ljava.io.File;@27b8a0a2, 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.354s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[1]([Ljava.io.File;@303438db, 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.363s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[2]([Ljava.io.File;@50332a1c, 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.378s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[3]([Ljava.io.File;@7c4597f0, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.321s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[4]([Ljava.io.File;@2989184d, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.317s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[5]([Ljava.io.File;@42d65db7, 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.232s passed
testMarkDuplicatesSparkMarkingAllDuplicatesWithTagging[6]([Ljava.io.File;@23e9863c, 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.222s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[0]([Ljava.io.File;@1736fd8e, 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.341s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[1]([Ljava.io.File;@68704163, 90, 6, {Solexa-16419=[4, 4, 4, 0, 0, 0, 0.0, 0], Solexa-16416=[2, 2, 2, 0, 0, 0, 0.0, 0], Solexa-16404=[3, 9, 3, 0, 2, 0, 0.190476, 17], Solexa-16406=[1, 10, 1, 0, 0, 0, 0.0, 0], Solexa-16412=[3, 6, 3, 0, 1, 0, 0.133333, 15]}) 0.380s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[2]([Ljava.io.File;@1ea44470, 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.372s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[3]([Ljava.io.File;@3adec420, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.344s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[4]([Ljava.io.File;@76a75a34, 4, 2, {mylib=[0, 2, 0, 0, 1, 1, 0.5, 0]}) 0.319s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[5]([Ljava.io.File;@4bf05f23, 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.255s passed
testMarkDuplicatesSparkMarkingOpticalDuplicatesWithTagging[6]([Ljava.io.File;@5180d813, 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.257s passed
testMatePairFirstUnmapped 0.298s passed
testMatePairSecondUnmapped 0.325s passed
testNoReadGroupInRead 0.231s passed
testNonExistantReadGroupInRead 0.215s passed
testNullOpticalDuplicates 0.319s passed
testOpticalDuplicateClusterOneEndSamePositionOneCluster 0.323s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicatesWithinPixelDistance 0.291s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[0](RUNID:7:1203:2886:82292, RUNID:7:1205:3886:16834) 0.330s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[10](RUNID:7:1203:6886:16756, RUNID:7:1203:4886:26756) 0.307s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[11](RUNID:7:1203:2886:34756, RUNID:7:1203:2886:36756) 0.306s 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.290s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[14](RUNID:7:1203:2886:38756, RUNID:7:1203:2886:36756) 0.315s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[15](HK3T5CCXX160204:3:1112:11586:37067, HK3T5CCXX160204:3:1112:11586:32144) 0.297s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[1](RUNID:7:1203:2886:16756, RUNID:7:1205:3886:16756) 0.293s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[2](RUNID:7:1204:2886:16756, RUNID:7:1205:3886:16756) 0.295s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[3](RUNID:7:1205:2886:16756, RUNID:7:1205:3886:16756) 0.308s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[4](RUNID:7:1206:2886:16756, RUNID:7:1205:3886:16756) 0.301s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[5](RUNID:7:1207:2886:16756, RUNID:7:1205:3886:16756) 0.313s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[6](RUNID:7:1203:2886:16756, RUNID:7:1203:4886:26756) 0.311s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[7](RUNID:7:1203:3886:16756, RUNID:7:1203:4886:26756) 0.297s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[8](RUNID:7:1203:4886:16756, RUNID:7:1203:4886:26756) 0.310s passed
testOpticalDuplicateClusterSamePositionNoOpticalDuplicates[9](RUNID:7:1203:5886:16756, RUNID:7:1203:4886:26756) 0.297s passed
testOpticalDuplicateClusterSamePositionOneOpticalDuplicatesWithinPixelDistance 0.307s passed
testOpticalDuplicateClustersAddingSecondEndFirstSameCoordinate 0.297s passed
testOpticalDuplicateFinding 0.305s passed
testOpticalDuplicateFindingPxelDistance 0.298s passed
testOpticalDuplicatesAndPCRDuplicatesOrientationDifference 0.303s passed
testOpticalDuplicatesDifferentReadGroups 0.299s passed
testOpticalDuplicatesTheSameReadGroup 0.305s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[0](RUNID:7:1203:2886:82292, RUNID:7:1205:3886:16834) 0.302s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[10](RUNID:7:1203:6886:16756, RUNID:7:1203:4886:26756) 0.291s 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.330s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[13](RUNID:7:1203:2886:37756, RUNID:7:1203:2886:36756) 0.302s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[14](RUNID:7:1203:2886:38756, RUNID:7:1203:2886:36756) 0.310s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[15](HK3T5CCXX160204:3:1112:11586:37067, HK3T5CCXX160204:3:1112:11586:32144) 0.299s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[1](RUNID:7:1203:2886:16756, RUNID:7:1205:3886:16756) 0.317s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[2](RUNID:7:1204:2886:16756, RUNID:7:1205:3886:16756) 0.306s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[3](RUNID:7:1205:2886:16756, RUNID:7:1205:3886:16756) 0.300s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[4](RUNID:7:1206:2886:16756, RUNID:7:1205:3886:16756) 0.295s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[5](RUNID:7:1207:2886:16756, RUNID:7:1205:3886:16756) 0.303s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[6](RUNID:7:1203:2886:16756, RUNID:7:1203:4886:26756) 0.307s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[7](RUNID:7:1203:3886:16756, RUNID:7:1203:4886:26756) 0.306s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[8](RUNID:7:1203:4886:16756, RUNID:7:1203:4886:26756) 0.320s passed
testOpticalDuplicatesTiebrokenByPhysicalLocationNotStartPosition[9](RUNID:7:1203:5886:16756, RUNID:7:1203:4886:26756) 0.312s passed
testPathologicalOrderingAtTheSamePosition 0.307s passed
testReadSameStartPositionOrientationOverride 0.318s passed
testReadsHaveSameStartPositionButDifferentChromosomeNonEquivalence 0.303s passed
testSecondEndIsBeforeFirstInCoordinate 0.292s passed
testSingleMappedFragment 0.300s passed
testSingleMappedFragmentAndSingleMappedPair 0.307s passed
testSingleMappedFragmentAndTwoMappedPairs 0.307s passed
testSingleMappedPair 0.311s passed
testSingleUnmappedFragment 0.295s passed
testSingleUnmappedPair 0.296s passed
testStackOverFlowPairSetSwap 0.306s passed
testSupplementaryReadUnmappedMate 0.305s passed
testThreeGroupsOnDifferentChromosomesOfThreeMappedPairs 0.319s passed
testThreeMappedPairs 0.309s passed
testThreeMappedPairsWithMatchingSecondMate 0.312s passed
testTwoGroupsOnDifferentChromosomesOfThreeMappedPairs 0.297s passed
testTwoGroupsOnDifferentChromosomesOfTwoFragments 0.293s passed
testTwoGroupsOnDifferentChromosomesOfTwoMappedPairs 0.297s passed
testTwoMappedFragments 0.329s passed
testTwoMappedPairWithSamePosition 0.310s passed
testTwoMappedPairWithSamePositionDifferentStrands 0.309s passed
testTwoMappedPairWithSamePositionDifferentStrands2 0.304s passed
testTwoMappedPairs 0.297s passed
testTwoMappedPairsAndMappedSecondaryFragment 0.306s passed
testTwoMappedPairsAndTerminalUnmappedFragment 0.304s passed
testTwoMappedPairsAndTerminalUnmappedPair 0.303s passed
testTwoMappedPairsMatesSoftClipped 0.290s passed
testTwoMappedPairsWithOppositeOrientations 0.296s passed
testTwoMappedPairsWithOppositeOrientationsNumberTwo 0.306s passed
testTwoMappedPairsWithSoftClipping 0.324s passed
testTwoMappedPairsWithSoftClippingBoth 0.299s passed
testTwoMappedPairsWithSoftClippingFirstOfPairOnly 0.315s passed
testTwoMappedPairsWithSoftClippingFirstOfPairOnlyNoMateCigar 0.303s passed
testTwoMappedPairsWithSupplementaryReads[0](true, true, true) 0.296s passed
testTwoMappedPairsWithSupplementaryReads[1](true, false, true) 0.307s passed
testTwoMappedPairsWithSupplementaryReads[2](false, true, true) 0.291s passed
testTwoMappedPairsWithSupplementaryReads[3](true, true, false) 0.293s passed
testTwoMappedPairsWithSupplementaryReads[4](true, false, false) 0.294s passed
testTwoMappedPairsWithSupplementaryReads[5](false, true, false) 0.300s passed
testTwoUnmappedFragments 0.303s passed

Standard error

[May 19, 2025 at 6:59:20 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:20 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:20 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:22 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:23 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
18:59:23.654 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:23.654 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:59:23.654 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:59:23.655 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:59:23.655 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:59:23.655 INFO  MarkDuplicatesSpark - Start Date/Time: May 19, 2025 at 6:59:23 PM UTC
18:59:23.655 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:23.655 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:23.655 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:59:23.655 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:59:23.655 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:59:23.655 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:59:23.655 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:59:23.655 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:59:23.655 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:59:23.655 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:59:23.655 INFO  MarkDuplicatesSpark - Initializing engine
18:59:23.655 INFO  MarkDuplicatesSpark - Done initializing engine
18:59:23.655 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:59:23.658 INFO  MemoryStore - Block broadcast_1371 stored as values in memory (estimated size 306.3 KiB, free 1899.3 MiB)
18:59:23.665 INFO  MemoryStore - Block broadcast_1371_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1899.2 MiB)
18:59:23.665 INFO  BlockManagerInfo - Added broadcast_1371_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1918.9 MiB)
18:59:23.665 INFO  SparkContext - Created broadcast 1371 from newAPIHadoopFile at PathSplitSource.java:96
18:59:23.685 INFO  MemoryStore - Block broadcast_1372 stored as values in memory (estimated size 306.3 KiB, free 1898.9 MiB)
18:59:23.692 INFO  MemoryStore - Block broadcast_1372_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1898.9 MiB)
18:59:23.692 INFO  BlockManagerInfo - Added broadcast_1372_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1918.9 MiB)
18:59:23.692 INFO  SparkContext - Created broadcast 1372 from newAPIHadoopFile at PathSplitSource.java:96
18:59:23.725 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:59:23.725 INFO  FileInputFormat - Total input files to process : 1
18:59:23.726 INFO  DAGScheduler - Registering RDD 3483 (mapToPair at SparkUtils.java:161) as input to shuffle 100
18:59:23.726 INFO  DAGScheduler - Got job 423 (collect at SparkUtils.java:205) with 1 output partitions
18:59:23.726 INFO  DAGScheduler - Final stage: ResultStage 735 (collect at SparkUtils.java:205)
18:59:23.726 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 734)
18:59:23.727 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 734)
18:59:23.727 INFO  DAGScheduler - Submitting ShuffleMapStage 734 (MapPartitionsRDD[3483] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:23.744 INFO  MemoryStore - Block broadcast_1373 stored as values in memory (estimated size 460.4 KiB, free 1898.4 MiB)
18:59:23.746 INFO  MemoryStore - Block broadcast_1373_piece0 stored as bytes in memory (estimated size 202.5 KiB, free 1898.2 MiB)
18:59:23.746 INFO  BlockManagerInfo - Added broadcast_1373_piece0 in memory on localhost:40133 (size: 202.5 KiB, free: 1918.7 MiB)
18:59:23.747 INFO  SparkContext - Created broadcast 1373 from broadcast at DAGScheduler.scala:1580
18:59:23.747 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:59:23.747 INFO  TaskSchedulerImpl - Adding task set 734.0 with 1 tasks resource profile 0
18:59:23.748 INFO  TaskSetManager - Starting task 0.0 in stage 734.0 (TID 676) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9735 bytes) 
18:59:23.749 INFO  Executor - Running task 0.0 in stage 734.0 (TID 676)
18:59:23.779 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug.bam:0+1507
18:59:23.784 INFO  Executor - Finished task 0.0 in stage 734.0 (TID 676). 1148 bytes result sent to driver
18:59:23.784 INFO  TaskSetManager - Finished task 0.0 in stage 734.0 (TID 676) in 36 ms on localhost (executor driver) (1/1)
18:59:23.784 INFO  TaskSchedulerImpl - Removed TaskSet 734.0, whose tasks have all completed, from pool 
18:59:23.784 INFO  DAGScheduler - ShuffleMapStage 734 (mapToPair at SparkUtils.java:161) finished in 0.057 s
18:59:23.784 INFO  DAGScheduler - looking for newly runnable stages
18:59:23.785 INFO  DAGScheduler - running: HashSet()
18:59:23.785 INFO  DAGScheduler - waiting: HashSet(ResultStage 735)
18:59:23.785 INFO  DAGScheduler - failed: HashSet()
18:59:23.785 INFO  DAGScheduler - Submitting ResultStage 735 (MapPartitionsRDD[3486] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:59:23.786 INFO  MemoryStore - Block broadcast_1374 stored as values in memory (estimated size 7.4 KiB, free 1898.2 MiB)
18:59:23.786 INFO  MemoryStore - Block broadcast_1374_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1898.2 MiB)
18:59:23.786 INFO  BlockManagerInfo - Added broadcast_1374_piece0 in memory on localhost:40133 (size: 4.1 KiB, free: 1918.7 MiB)
18:59:23.786 INFO  SparkContext - Created broadcast 1374 from broadcast at DAGScheduler.scala:1580
18:59:23.787 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:59:23.787 INFO  TaskSchedulerImpl - Adding task set 735.0 with 1 tasks resource profile 0
18:59:23.787 INFO  TaskSetManager - Starting task 0.0 in stage 735.0 (TID 677) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:23.787 INFO  Executor - Running task 0.0 in stage 735.0 (TID 677)
18:59:23.789 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:59:23.789 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.791 INFO  Executor - Finished task 0.0 in stage 735.0 (TID 677). 2238 bytes result sent to driver
18:59:23.791 INFO  TaskSetManager - Finished task 0.0 in stage 735.0 (TID 677) in 4 ms on localhost (executor driver) (1/1)
18:59:23.791 INFO  TaskSchedulerImpl - Removed TaskSet 735.0, whose tasks have all completed, from pool 
18:59:23.791 INFO  DAGScheduler - ResultStage 735 (collect at SparkUtils.java:205) finished in 0.006 s
18:59:23.791 INFO  DAGScheduler - Job 423 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:23.791 INFO  TaskSchedulerImpl - Killing all running tasks in stage 735: Stage finished
18:59:23.792 INFO  DAGScheduler - Job 423 finished: collect at SparkUtils.java:205, took 0.066652 s
18:59:23.796 INFO  MemoryStore - Block broadcast_1375 stored as values in memory (estimated size 1632.0 B, free 1898.2 MiB)
18:59:23.796 INFO  MemoryStore - Block broadcast_1375_piece0 stored as bytes in memory (estimated size 145.0 B, free 1898.2 MiB)
18:59:23.797 INFO  BlockManagerInfo - Added broadcast_1375_piece0 in memory on localhost:40133 (size: 145.0 B, free: 1918.7 MiB)
18:59:23.797 INFO  SparkContext - Created broadcast 1375 from broadcast at MarkDuplicatesSparkUtils.java:126
18:59:23.797 INFO  MemoryStore - Block broadcast_1376 stored as values in memory (estimated size 304.0 B, free 1898.2 MiB)
18:59:23.797 INFO  MemoryStore - Block broadcast_1376_piece0 stored as bytes in memory (estimated size 37.0 B, free 1898.2 MiB)
18:59:23.798 INFO  BlockManagerInfo - Added broadcast_1376_piece0 in memory on localhost:40133 (size: 37.0 B, free: 1918.7 MiB)
18:59:23.798 INFO  SparkContext - Created broadcast 1376 from broadcast at MarkDuplicatesSparkUtils.java:127
18:59:23.810 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:59:23.810 INFO  DAGScheduler - Registering RDD 3495 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 103
18:59:23.810 INFO  DAGScheduler - Registering RDD 3499 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 102
18:59:23.810 INFO  DAGScheduler - Registering RDD 3503 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 101
18:59:23.810 INFO  DAGScheduler - Got job 424 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:59:23.810 INFO  DAGScheduler - Final stage: ResultStage 740 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:59:23.811 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 739)
18:59:23.811 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 739)
18:59:23.811 INFO  DAGScheduler - Submitting ShuffleMapStage 737 (MapPartitionsRDD[3495] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:59:23.811 INFO  MemoryStore - Block broadcast_1377 stored as values in memory (estimated size 24.2 KiB, free 1898.2 MiB)
18:59:23.812 INFO  MemoryStore - Block broadcast_1377_piece0 stored as bytes in memory (estimated size 12.6 KiB, free 1898.2 MiB)
18:59:23.812 INFO  BlockManagerInfo - Added broadcast_1377_piece0 in memory on localhost:40133 (size: 12.6 KiB, free: 1918.7 MiB)
18:59:23.812 INFO  SparkContext - Created broadcast 1377 from broadcast at DAGScheduler.scala:1580
18:59:23.812 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:59:23.812 INFO  TaskSchedulerImpl - Adding task set 737.0 with 1 tasks resource profile 0
18:59:23.813 INFO  TaskSetManager - Starting task 0.0 in stage 737.0 (TID 678) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:59:23.813 INFO  Executor - Running task 0.0 in stage 737.0 (TID 678)
18:59:23.815 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:59:23.815 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.818 INFO  Executor - Finished task 0.0 in stage 737.0 (TID 678). 1922 bytes result sent to driver
18:59:23.818 INFO  TaskSetManager - Finished task 0.0 in stage 737.0 (TID 678) in 5 ms on localhost (executor driver) (1/1)
18:59:23.818 INFO  TaskSchedulerImpl - Removed TaskSet 737.0, whose tasks have all completed, from pool 
18:59:23.818 INFO  DAGScheduler - ShuffleMapStage 737 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.007 s
18:59:23.818 INFO  DAGScheduler - looking for newly runnable stages
18:59:23.818 INFO  DAGScheduler - running: HashSet()
18:59:23.819 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 738, ShuffleMapStage 739, ResultStage 740)
18:59:23.819 INFO  DAGScheduler - failed: HashSet()
18:59:23.819 INFO  DAGScheduler - Submitting ShuffleMapStage 738 (MapPartitionsRDD[3499] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:59:23.820 INFO  MemoryStore - Block broadcast_1378 stored as values in memory (estimated size 28.3 KiB, free 1898.2 MiB)
18:59:23.820 INFO  MemoryStore - Block broadcast_1378_piece0 stored as bytes in memory (estimated size 14.8 KiB, free 1898.1 MiB)
18:59:23.820 INFO  BlockManagerInfo - Added broadcast_1378_piece0 in memory on localhost:40133 (size: 14.8 KiB, free: 1918.6 MiB)
18:59:23.820 INFO  SparkContext - Created broadcast 1378 from broadcast at DAGScheduler.scala:1580
18:59:23.821 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:59:23.821 INFO  TaskSchedulerImpl - Adding task set 738.0 with 1 tasks resource profile 0
18:59:23.821 INFO  TaskSetManager - Starting task 0.0 in stage 738.0 (TID 679) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:59:23.821 INFO  Executor - Running task 0.0 in stage 738.0 (TID 679)
18:59:23.823 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:59:23.823 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.827 INFO  Executor - Finished task 0.0 in stage 738.0 (TID 679). 1922 bytes result sent to driver
18:59:23.827 INFO  TaskSetManager - Finished task 0.0 in stage 738.0 (TID 679) in 6 ms on localhost (executor driver) (1/1)
18:59:23.827 INFO  TaskSchedulerImpl - Removed TaskSet 738.0, whose tasks have all completed, from pool 
18:59:23.827 INFO  DAGScheduler - ShuffleMapStage 738 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.008 s
18:59:23.827 INFO  DAGScheduler - looking for newly runnable stages
18:59:23.828 INFO  DAGScheduler - running: HashSet()
18:59:23.828 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 739, ResultStage 740)
18:59:23.828 INFO  DAGScheduler - failed: HashSet()
18:59:23.828 INFO  DAGScheduler - Submitting ShuffleMapStage 739 (MapPartitionsRDD[3503] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:59:23.828 INFO  MemoryStore - Block broadcast_1379 stored as values in memory (estimated size 19.0 KiB, free 1898.1 MiB)
18:59:23.829 INFO  MemoryStore - Block broadcast_1379_piece0 stored as bytes in memory (estimated size 9.7 KiB, free 1898.1 MiB)
18:59:23.829 INFO  BlockManagerInfo - Added broadcast_1379_piece0 in memory on localhost:40133 (size: 9.7 KiB, free: 1918.6 MiB)
18:59:23.829 INFO  SparkContext - Created broadcast 1379 from broadcast at DAGScheduler.scala:1580
18:59:23.829 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:59:23.829 INFO  TaskSchedulerImpl - Adding task set 739.0 with 1 tasks resource profile 0
18:59:23.830 INFO  TaskSetManager - Starting task 0.0 in stage 739.0 (TID 680) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:23.830 INFO  Executor - Running task 0.0 in stage 739.0 (TID 680)
18:59:23.832 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:59:23.832 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.835 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:59:23.835 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.836 INFO  Executor - Finished task 0.0 in stage 739.0 (TID 680). 1922 bytes result sent to driver
18:59:23.837 INFO  TaskSetManager - Finished task 0.0 in stage 739.0 (TID 680) in 6 ms on localhost (executor driver) (1/1)
18:59:23.837 INFO  TaskSchedulerImpl - Removed TaskSet 739.0, whose tasks have all completed, from pool 
18:59:23.837 INFO  DAGScheduler - ShuffleMapStage 739 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.009 s
18:59:23.837 INFO  DAGScheduler - looking for newly runnable stages
18:59:23.837 INFO  DAGScheduler - running: HashSet()
18:59:23.837 INFO  DAGScheduler - waiting: HashSet(ResultStage 740)
18:59:23.837 INFO  DAGScheduler - failed: HashSet()
18:59:23.837 INFO  DAGScheduler - Submitting ResultStage 740 (MapPartitionsRDD[3505] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:59:23.838 INFO  MemoryStore - Block broadcast_1380 stored as values in memory (estimated size 20.2 KiB, free 1898.1 MiB)
18:59:23.839 INFO  MemoryStore - Block broadcast_1380_piece0 stored as bytes in memory (estimated size 10.6 KiB, free 1898.1 MiB)
18:59:23.839 INFO  BlockManagerInfo - Added broadcast_1380_piece0 in memory on localhost:40133 (size: 10.6 KiB, free: 1918.6 MiB)
18:59:23.839 INFO  SparkContext - Created broadcast 1380 from broadcast at DAGScheduler.scala:1580
18:59:23.839 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:59:23.839 INFO  TaskSchedulerImpl - Adding task set 740.0 with 1 tasks resource profile 0
18:59:23.840 INFO  TaskSetManager - Starting task 0.0 in stage 740.0 (TID 681) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:23.840 INFO  Executor - Running task 0.0 in stage 740.0 (TID 681)
18:59:23.842 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:59:23.842 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.844 INFO  Executor - Finished task 0.0 in stage 740.0 (TID 681). 1944 bytes result sent to driver
18:59:23.844 INFO  TaskSetManager - Finished task 0.0 in stage 740.0 (TID 681) in 5 ms on localhost (executor driver) (1/1)
18:59:23.844 INFO  TaskSchedulerImpl - Removed TaskSet 740.0, whose tasks have all completed, from pool 
18:59:23.844 INFO  DAGScheduler - ResultStage 740 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.007 s
18:59:23.845 INFO  DAGScheduler - Job 424 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:23.845 INFO  TaskSchedulerImpl - Killing all running tasks in stage 740: Stage finished
18:59:23.845 INFO  DAGScheduler - Job 424 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.035323 s
18:59:23.859 INFO  MemoryStore - Block broadcast_1381 stored as values in memory (estimated size 20.3 KiB, free 1898.1 MiB)
18:59:23.859 INFO  MemoryStore - Block broadcast_1381_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1898.1 MiB)
18:59:23.860 INFO  BlockManagerInfo - Added broadcast_1381_piece0 in memory on localhost:40133 (size: 1850.0 B, free: 1918.6 MiB)
18:59:23.860 INFO  SparkContext - Created broadcast 1381 from broadcast at ReadsSparkSink.java:133
18:59:23.861 INFO  MemoryStore - Block broadcast_1382 stored as values in memory (estimated size 20.4 KiB, free 1898.0 MiB)
18:59:23.861 INFO  MemoryStore - Block broadcast_1382_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1898.0 MiB)
18:59:23.862 INFO  BlockManagerInfo - Added broadcast_1382_piece0 in memory on localhost:40133 (size: 1850.0 B, free: 1918.6 MiB)
18:59:23.862 INFO  SparkContext - Created broadcast 1382 from broadcast at BamSink.java:76
18:59:23.864 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:59:23.864 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:23.864 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:23.884 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:59:23.885 INFO  DAGScheduler - Registering RDD 3507 (mapToPair at SparkUtils.java:161) as input to shuffle 104
18:59:23.885 INFO  DAGScheduler - Got job 425 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:59:23.885 INFO  DAGScheduler - Final stage: ResultStage 745 (runJob at SparkHadoopWriter.scala:83)
18:59:23.885 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 744)
18:59:23.885 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 744)
18:59:23.885 INFO  DAGScheduler - Submitting ShuffleMapStage 744 (MapPartitionsRDD[3507] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:23.886 INFO  MemoryStore - Block broadcast_1383 stored as values in memory (estimated size 18.1 KiB, free 1898.0 MiB)
18:59:23.887 INFO  MemoryStore - Block broadcast_1383_piece0 stored as bytes in memory (estimated size 9.5 KiB, free 1898.0 MiB)
18:59:23.887 INFO  BlockManagerInfo - Added broadcast_1383_piece0 in memory on localhost:40133 (size: 9.5 KiB, free: 1918.6 MiB)
18:59:23.887 INFO  SparkContext - Created broadcast 1383 from broadcast at DAGScheduler.scala:1580
18:59:23.888 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:59:23.888 INFO  TaskSchedulerImpl - Adding task set 744.0 with 1 tasks resource profile 0
18:59:23.888 INFO  TaskSetManager - Starting task 0.0 in stage 744.0 (TID 682) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:23.888 INFO  Executor - Running task 0.0 in stage 744.0 (TID 682)
18:59:23.890 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:59:23.890 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.892 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:59:23.893 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.894 INFO  Executor - Finished task 0.0 in stage 744.0 (TID 682). 1922 bytes result sent to driver
18:59:23.894 INFO  TaskSetManager - Finished task 0.0 in stage 744.0 (TID 682) in 6 ms on localhost (executor driver) (1/1)
18:59:23.894 INFO  TaskSchedulerImpl - Removed TaskSet 744.0, whose tasks have all completed, from pool 
18:59:23.895 INFO  DAGScheduler - ShuffleMapStage 744 (mapToPair at SparkUtils.java:161) finished in 0.009 s
18:59:23.895 INFO  DAGScheduler - looking for newly runnable stages
18:59:23.895 INFO  DAGScheduler - running: HashSet()
18:59:23.895 INFO  DAGScheduler - waiting: HashSet(ResultStage 745)
18:59:23.895 INFO  DAGScheduler - failed: HashSet()
18:59:23.895 INFO  DAGScheduler - Submitting ResultStage 745 (MapPartitionsRDD[3512] at mapToPair at BamSink.java:91), which has no missing parents
18:59:23.903 INFO  MemoryStore - Block broadcast_1384 stored as values in memory (estimated size 163.7 KiB, free 1897.9 MiB)
18:59:23.904 INFO  MemoryStore - Block broadcast_1384_piece0 stored as bytes in memory (estimated size 73.9 KiB, free 1897.8 MiB)
18:59:23.904 INFO  BlockManagerInfo - Added broadcast_1384_piece0 in memory on localhost:40133 (size: 73.9 KiB, free: 1918.5 MiB)
18:59:23.904 INFO  SparkContext - Created broadcast 1384 from broadcast at DAGScheduler.scala:1580
18:59:23.905 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:59:23.905 INFO  TaskSchedulerImpl - Adding task set 745.0 with 1 tasks resource profile 0
18:59:23.905 INFO  TaskSetManager - Starting task 0.0 in stage 745.0 (TID 683) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:23.905 INFO  Executor - Running task 0.0 in stage 745.0 (TID 683)
18:59:23.909 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:59:23.909 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:23.911 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:59:23.911 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:23.911 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:23.911 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:59:23.911 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:23.911 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:23.929 INFO  FileOutputCommitter - Saved output of task 'attempt_202505191859231934356064934970495_3512_r_000000_0' to file:/tmp/local12542579939630629552/markdups2639678053517721289.bam.parts/_temporary/0/task_202505191859231934356064934970495_3512_r_000000
18:59:23.929 INFO  SparkHadoopMapRedUtil - attempt_202505191859231934356064934970495_3512_r_000000_0: Committed. Elapsed time: 0 ms.
18:59:23.929 INFO  Executor - Finished task 0.0 in stage 745.0 (TID 683). 1858 bytes result sent to driver
18:59:23.930 INFO  TaskSetManager - Finished task 0.0 in stage 745.0 (TID 683) in 25 ms on localhost (executor driver) (1/1)
18:59:23.930 INFO  TaskSchedulerImpl - Removed TaskSet 745.0, whose tasks have all completed, from pool 
18:59:23.930 INFO  DAGScheduler - ResultStage 745 (runJob at SparkHadoopWriter.scala:83) finished in 0.035 s
18:59:23.930 INFO  DAGScheduler - Job 425 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:23.930 INFO  TaskSchedulerImpl - Killing all running tasks in stage 745: Stage finished
18:59:23.930 INFO  DAGScheduler - Job 425 finished: runJob at SparkHadoopWriter.scala:83, took 0.045742 s
18:59:23.930 INFO  SparkHadoopWriter - Start to commit write Job job_202505191859231934356064934970495_3512.
18:59:23.935 INFO  SparkHadoopWriter - Write Job job_202505191859231934356064934970495_3512 committed. Elapsed time: 4 ms.
18:59:23.945 INFO  HadoopFileSystemWrapper - Concatenating 3 parts to /tmp/local12542579939630629552/markdups2639678053517721289.bam
18:59:23.948 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/local12542579939630629552/markdups2639678053517721289.bam done
18:59:23.949 INFO  IndexFileMerger - Merging .sbi files in temp directory /tmp/local12542579939630629552/markdups2639678053517721289.bam.parts/ to /tmp/local12542579939630629552/markdups2639678053517721289.bam.sbi
18:59:23.953 INFO  IndexFileMerger - Done merging .sbi files
18:59:23.953 INFO  IndexFileMerger - Merging .bai files in temp directory /tmp/local12542579939630629552/markdups2639678053517721289.bam.parts/ to /tmp/local12542579939630629552/markdups2639678053517721289.bam.bai
18:59:23.957 INFO  IndexFileMerger - Done merging .bai files
18:59:23.957 INFO  MarkDuplicatesSpark - Shutting down engine
[May 19, 2025 at 6:59:23 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
18:59:23.965 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:23.965 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:59:23.965 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:59:23.965 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:59:23.965 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:59:23.965 INFO  MarkDuplicatesSpark - Start Date/Time: May 19, 2025 at 6:59:23 PM UTC
18:59:23.965 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:23.965 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:23.965 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:59:23.965 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:59:23.965 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:59:23.965 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:59:23.965 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:59:23.965 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:59:23.965 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:59:23.965 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:59:23.965 INFO  MarkDuplicatesSpark - Initializing engine
18:59:23.965 INFO  MarkDuplicatesSpark - Done initializing engine
18:59:23.965 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:59:23.968 INFO  MemoryStore - Block broadcast_1385 stored as values in memory (estimated size 306.3 KiB, free 1897.5 MiB)
18:59:23.974 INFO  MemoryStore - Block broadcast_1385_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1897.4 MiB)
18:59:23.975 INFO  BlockManagerInfo - Added broadcast_1385_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1918.5 MiB)
18:59:23.975 INFO  SparkContext - Created broadcast 1385 from newAPIHadoopFile at PathSplitSource.java:96
18:59:23.995 INFO  MemoryStore - Block broadcast_1386 stored as values in memory (estimated size 306.3 KiB, free 1897.1 MiB)
18:59:24.002 INFO  MemoryStore - Block broadcast_1386_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1897.1 MiB)
18:59:24.002 INFO  BlockManagerInfo - Added broadcast_1386_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1918.4 MiB)
18:59:24.002 INFO  SparkContext - Created broadcast 1386 from newAPIHadoopFile at PathSplitSource.java:96
18:59:24.034 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:59:24.035 INFO  FileInputFormat - Total input files to process : 1
18:59:24.035 INFO  DAGScheduler - Registering RDD 3526 (mapToPair at SparkUtils.java:161) as input to shuffle 105
18:59:24.035 INFO  DAGScheduler - Got job 426 (collect at SparkUtils.java:205) with 1 output partitions
18:59:24.035 INFO  DAGScheduler - Final stage: ResultStage 747 (collect at SparkUtils.java:205)
18:59:24.035 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 746)
18:59:24.035 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 746)
18:59:24.036 INFO  DAGScheduler - Submitting ShuffleMapStage 746 (MapPartitionsRDD[3526] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:24.052 INFO  MemoryStore - Block broadcast_1387 stored as values in memory (estimated size 460.4 KiB, free 1896.6 MiB)
18:59:24.055 INFO  MemoryStore - Block broadcast_1387_piece0 stored as bytes in memory (estimated size 202.5 KiB, free 1896.4 MiB)
18:59:24.055 INFO  BlockManagerInfo - Added broadcast_1387_piece0 in memory on localhost:40133 (size: 202.5 KiB, free: 1918.2 MiB)
18:59:24.055 INFO  SparkContext - Created broadcast 1387 from broadcast at DAGScheduler.scala:1580
18:59:24.055 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:59:24.055 INFO  TaskSchedulerImpl - Adding task set 746.0 with 1 tasks resource profile 0
18:59:24.056 INFO  TaskSetManager - Starting task 0.0 in stage 746.0 (TID 684) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9736 bytes) 
18:59:24.056 INFO  Executor - Running task 0.0 in stage 746.0 (TID 684)
18:59:24.086 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/mdOrderBug2.bam:0+1856
18:59:24.090 INFO  Executor - Finished task 0.0 in stage 746.0 (TID 684). 1148 bytes result sent to driver
18:59:24.090 INFO  TaskSetManager - Finished task 0.0 in stage 746.0 (TID 684) in 34 ms on localhost (executor driver) (1/1)
18:59:24.090 INFO  TaskSchedulerImpl - Removed TaskSet 746.0, whose tasks have all completed, from pool 
18:59:24.091 INFO  DAGScheduler - ShuffleMapStage 746 (mapToPair at SparkUtils.java:161) finished in 0.054 s
18:59:24.091 INFO  DAGScheduler - looking for newly runnable stages
18:59:24.091 INFO  DAGScheduler - running: HashSet()
18:59:24.091 INFO  DAGScheduler - waiting: HashSet(ResultStage 747)
18:59:24.091 INFO  DAGScheduler - failed: HashSet()
18:59:24.091 INFO  DAGScheduler - Submitting ResultStage 747 (MapPartitionsRDD[3529] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:59:24.091 INFO  MemoryStore - Block broadcast_1388 stored as values in memory (estimated size 7.4 KiB, free 1896.4 MiB)
18:59:24.092 INFO  MemoryStore - Block broadcast_1388_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1896.4 MiB)
18:59:24.092 INFO  BlockManagerInfo - Added broadcast_1388_piece0 in memory on localhost:40133 (size: 4.1 KiB, free: 1918.2 MiB)
18:59:24.092 INFO  SparkContext - Created broadcast 1388 from broadcast at DAGScheduler.scala:1580
18:59:24.092 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:59:24.092 INFO  TaskSchedulerImpl - Adding task set 747.0 with 1 tasks resource profile 0
18:59:24.093 INFO  TaskSetManager - Starting task 0.0 in stage 747.0 (TID 685) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:24.093 INFO  Executor - Running task 0.0 in stage 747.0 (TID 685)
18:59:24.094 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:59:24.094 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.096 INFO  Executor - Finished task 0.0 in stage 747.0 (TID 685). 2495 bytes result sent to driver
18:59:24.096 INFO  TaskSetManager - Finished task 0.0 in stage 747.0 (TID 685) in 3 ms on localhost (executor driver) (1/1)
18:59:24.096 INFO  TaskSchedulerImpl - Removed TaskSet 747.0, whose tasks have all completed, from pool 
18:59:24.097 INFO  DAGScheduler - ResultStage 747 (collect at SparkUtils.java:205) finished in 0.005 s
18:59:24.097 INFO  DAGScheduler - Job 426 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:24.097 INFO  TaskSchedulerImpl - Killing all running tasks in stage 747: Stage finished
18:59:24.097 INFO  DAGScheduler - Job 426 finished: collect at SparkUtils.java:205, took 0.062423 s
18:59:24.101 INFO  MemoryStore - Block broadcast_1389 stored as values in memory (estimated size 1632.0 B, free 1896.4 MiB)
18:59:24.101 INFO  MemoryStore - Block broadcast_1389_piece0 stored as bytes in memory (estimated size 145.0 B, free 1896.4 MiB)
18:59:24.102 INFO  BlockManagerInfo - Added broadcast_1389_piece0 in memory on localhost:40133 (size: 145.0 B, free: 1918.2 MiB)
18:59:24.102 INFO  SparkContext - Created broadcast 1389 from broadcast at MarkDuplicatesSparkUtils.java:126
18:59:24.102 INFO  MemoryStore - Block broadcast_1390 stored as values in memory (estimated size 304.0 B, free 1896.4 MiB)
18:59:24.102 INFO  MemoryStore - Block broadcast_1390_piece0 stored as bytes in memory (estimated size 37.0 B, free 1896.4 MiB)
18:59:24.103 INFO  BlockManagerInfo - Added broadcast_1390_piece0 in memory on localhost:40133 (size: 37.0 B, free: 1918.2 MiB)
18:59:24.103 INFO  SparkContext - Created broadcast 1390 from broadcast at MarkDuplicatesSparkUtils.java:127
18:59:24.120 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:59:24.121 INFO  DAGScheduler - Registering RDD 3538 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 108
18:59:24.121 INFO  DAGScheduler - Registering RDD 3542 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 107
18:59:24.121 INFO  DAGScheduler - Registering RDD 3546 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 106
18:59:24.121 INFO  DAGScheduler - Got job 427 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:59:24.121 INFO  DAGScheduler - Final stage: ResultStage 752 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:59:24.121 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 751)
18:59:24.121 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 751)
18:59:24.121 INFO  DAGScheduler - Submitting ShuffleMapStage 749 (MapPartitionsRDD[3538] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:59:24.122 INFO  MemoryStore - Block broadcast_1391 stored as values in memory (estimated size 24.2 KiB, free 1896.4 MiB)
18:59:24.123 INFO  MemoryStore - Block broadcast_1391_piece0 stored as bytes in memory (estimated size 12.6 KiB, free 1896.4 MiB)
18:59:24.123 INFO  BlockManagerInfo - Added broadcast_1391_piece0 in memory on localhost:40133 (size: 12.6 KiB, free: 1918.2 MiB)
18:59:24.123 INFO  SparkContext - Created broadcast 1391 from broadcast at DAGScheduler.scala:1580
18:59:24.123 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:59:24.123 INFO  TaskSchedulerImpl - Adding task set 749.0 with 1 tasks resource profile 0
18:59:24.124 INFO  TaskSetManager - Starting task 0.0 in stage 749.0 (TID 686) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:59:24.124 INFO  Executor - Running task 0.0 in stage 749.0 (TID 686)
18:59:24.126 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:59:24.126 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.130 INFO  Executor - Finished task 0.0 in stage 749.0 (TID 686). 1922 bytes result sent to driver
18:59:24.130 INFO  TaskSetManager - Finished task 0.0 in stage 749.0 (TID 686) in 6 ms on localhost (executor driver) (1/1)
18:59:24.130 INFO  TaskSchedulerImpl - Removed TaskSet 749.0, whose tasks have all completed, from pool 
18:59:24.130 INFO  DAGScheduler - ShuffleMapStage 749 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.008 s
18:59:24.130 INFO  DAGScheduler - looking for newly runnable stages
18:59:24.130 INFO  DAGScheduler - running: HashSet()
18:59:24.130 INFO  DAGScheduler - waiting: HashSet(ResultStage 752, ShuffleMapStage 750, ShuffleMapStage 751)
18:59:24.130 INFO  DAGScheduler - failed: HashSet()
18:59:24.130 INFO  DAGScheduler - Submitting ShuffleMapStage 750 (MapPartitionsRDD[3542] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:59:24.131 INFO  MemoryStore - Block broadcast_1392 stored as values in memory (estimated size 28.3 KiB, free 1896.3 MiB)
18:59:24.132 INFO  MemoryStore - Block broadcast_1392_piece0 stored as bytes in memory (estimated size 14.8 KiB, free 1896.3 MiB)
18:59:24.132 INFO  BlockManagerInfo - Added broadcast_1392_piece0 in memory on localhost:40133 (size: 14.8 KiB, free: 1918.2 MiB)
18:59:24.132 INFO  SparkContext - Created broadcast 1392 from broadcast at DAGScheduler.scala:1580
18:59:24.132 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:59:24.132 INFO  TaskSchedulerImpl - Adding task set 750.0 with 1 tasks resource profile 0
18:59:24.133 INFO  TaskSetManager - Starting task 0.0 in stage 750.0 (TID 687) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:59:24.133 INFO  Executor - Running task 0.0 in stage 750.0 (TID 687)
18:59:24.134 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:59:24.134 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.138 INFO  Executor - Finished task 0.0 in stage 750.0 (TID 687). 1922 bytes result sent to driver
18:59:24.139 INFO  TaskSetManager - Finished task 0.0 in stage 750.0 (TID 687) in 7 ms on localhost (executor driver) (1/1)
18:59:24.139 INFO  TaskSchedulerImpl - Removed TaskSet 750.0, whose tasks have all completed, from pool 
18:59:24.139 INFO  DAGScheduler - ShuffleMapStage 750 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.008 s
18:59:24.139 INFO  DAGScheduler - looking for newly runnable stages
18:59:24.139 INFO  DAGScheduler - running: HashSet()
18:59:24.139 INFO  DAGScheduler - waiting: HashSet(ResultStage 752, ShuffleMapStage 751)
18:59:24.139 INFO  DAGScheduler - failed: HashSet()
18:59:24.139 INFO  DAGScheduler - Submitting ShuffleMapStage 751 (MapPartitionsRDD[3546] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:59:24.140 INFO  MemoryStore - Block broadcast_1393 stored as values in memory (estimated size 19.0 KiB, free 1896.3 MiB)
18:59:24.140 INFO  MemoryStore - Block broadcast_1393_piece0 stored as bytes in memory (estimated size 9.7 KiB, free 1896.3 MiB)
18:59:24.140 INFO  BlockManagerInfo - Added broadcast_1393_piece0 in memory on localhost:40133 (size: 9.7 KiB, free: 1918.2 MiB)
18:59:24.141 INFO  SparkContext - Created broadcast 1393 from broadcast at DAGScheduler.scala:1580
18:59:24.141 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:59:24.141 INFO  TaskSchedulerImpl - Adding task set 751.0 with 1 tasks resource profile 0
18:59:24.141 INFO  TaskSetManager - Starting task 0.0 in stage 751.0 (TID 688) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:24.141 INFO  Executor - Running task 0.0 in stage 751.0 (TID 688)
18:59:24.143 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:59:24.143 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.144 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:59:24.144 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.146 INFO  Executor - Finished task 0.0 in stage 751.0 (TID 688). 1879 bytes result sent to driver
18:59:24.146 INFO  TaskSetManager - Finished task 0.0 in stage 751.0 (TID 688) in 5 ms on localhost (executor driver) (1/1)
18:59:24.146 INFO  TaskSchedulerImpl - Removed TaskSet 751.0, whose tasks have all completed, from pool 
18:59:24.146 INFO  DAGScheduler - ShuffleMapStage 751 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.007 s
18:59:24.146 INFO  DAGScheduler - looking for newly runnable stages
18:59:24.146 INFO  DAGScheduler - running: HashSet()
18:59:24.146 INFO  DAGScheduler - waiting: HashSet(ResultStage 752)
18:59:24.146 INFO  DAGScheduler - failed: HashSet()
18:59:24.146 INFO  DAGScheduler - Submitting ResultStage 752 (MapPartitionsRDD[3548] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:59:24.147 INFO  MemoryStore - Block broadcast_1394 stored as values in memory (estimated size 20.2 KiB, free 1896.3 MiB)
18:59:24.147 INFO  MemoryStore - Block broadcast_1394_piece0 stored as bytes in memory (estimated size 10.6 KiB, free 1896.3 MiB)
18:59:24.148 INFO  BlockManagerInfo - Added broadcast_1394_piece0 in memory on localhost:40133 (size: 10.6 KiB, free: 1918.2 MiB)
18:59:24.148 INFO  SparkContext - Created broadcast 1394 from broadcast at DAGScheduler.scala:1580
18:59:24.148 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:59:24.148 INFO  TaskSchedulerImpl - Adding task set 752.0 with 1 tasks resource profile 0
18:59:24.148 INFO  TaskSetManager - Starting task 0.0 in stage 752.0 (TID 689) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:24.149 INFO  Executor - Running task 0.0 in stage 752.0 (TID 689)
18:59:24.150 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:59:24.150 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.152 INFO  Executor - Finished task 0.0 in stage 752.0 (TID 689). 2053 bytes result sent to driver
18:59:24.153 INFO  TaskSetManager - Finished task 0.0 in stage 752.0 (TID 689) in 5 ms on localhost (executor driver) (1/1)
18:59:24.153 INFO  TaskSchedulerImpl - Removed TaskSet 752.0, whose tasks have all completed, from pool 
18:59:24.153 INFO  DAGScheduler - ResultStage 752 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.006 s
18:59:24.153 INFO  DAGScheduler - Job 427 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:24.153 INFO  TaskSchedulerImpl - Killing all running tasks in stage 752: Stage finished
18:59:24.153 INFO  DAGScheduler - Job 427 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.032824 s
18:59:24.168 INFO  MemoryStore - Block broadcast_1395 stored as values in memory (estimated size 20.3 KiB, free 1896.2 MiB)
18:59:24.168 INFO  MemoryStore - Block broadcast_1395_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1896.2 MiB)
18:59:24.168 INFO  BlockManagerInfo - Added broadcast_1395_piece0 in memory on localhost:40133 (size: 1850.0 B, free: 1918.2 MiB)
18:59:24.168 INFO  SparkContext - Created broadcast 1395 from broadcast at ReadsSparkSink.java:133
18:59:24.169 INFO  MemoryStore - Block broadcast_1396 stored as values in memory (estimated size 20.4 KiB, free 1896.2 MiB)
18:59:24.169 INFO  MemoryStore - Block broadcast_1396_piece0 stored as bytes in memory (estimated size 1850.0 B, free 1896.2 MiB)
18:59:24.170 INFO  BlockManagerInfo - Added broadcast_1396_piece0 in memory on localhost:40133 (size: 1850.0 B, free: 1918.2 MiB)
18:59:24.170 INFO  SparkContext - Created broadcast 1396 from broadcast at BamSink.java:76
18:59:24.171 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:59:24.171 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:24.171 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:24.189 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:59:24.189 INFO  DAGScheduler - Registering RDD 3550 (mapToPair at SparkUtils.java:161) as input to shuffle 109
18:59:24.189 INFO  DAGScheduler - Got job 428 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:59:24.189 INFO  DAGScheduler - Final stage: ResultStage 757 (runJob at SparkHadoopWriter.scala:83)
18:59:24.189 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 756)
18:59:24.189 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 756)
18:59:24.189 INFO  DAGScheduler - Submitting ShuffleMapStage 756 (MapPartitionsRDD[3550] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:24.190 INFO  MemoryStore - Block broadcast_1397 stored as values in memory (estimated size 18.1 KiB, free 1896.2 MiB)
18:59:24.191 INFO  MemoryStore - Block broadcast_1397_piece0 stored as bytes in memory (estimated size 9.5 KiB, free 1896.2 MiB)
18:59:24.191 INFO  BlockManagerInfo - Added broadcast_1397_piece0 in memory on localhost:40133 (size: 9.5 KiB, free: 1918.2 MiB)
18:59:24.191 INFO  SparkContext - Created broadcast 1397 from broadcast at DAGScheduler.scala:1580
18:59:24.191 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:59:24.191 INFO  TaskSchedulerImpl - Adding task set 756.0 with 1 tasks resource profile 0
18:59:24.192 INFO  TaskSetManager - Starting task 0.0 in stage 756.0 (TID 690) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:24.192 INFO  Executor - Running task 0.0 in stage 756.0 (TID 690)
18:59:24.194 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:59:24.194 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.196 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:59:24.196 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.198 INFO  Executor - Finished task 0.0 in stage 756.0 (TID 690). 1922 bytes result sent to driver
18:59:24.198 INFO  TaskSetManager - Finished task 0.0 in stage 756.0 (TID 690) in 6 ms on localhost (executor driver) (1/1)
18:59:24.198 INFO  TaskSchedulerImpl - Removed TaskSet 756.0, whose tasks have all completed, from pool 
18:59:24.198 INFO  DAGScheduler - ShuffleMapStage 756 (mapToPair at SparkUtils.java:161) finished in 0.008 s
18:59:24.198 INFO  DAGScheduler - looking for newly runnable stages
18:59:24.198 INFO  DAGScheduler - running: HashSet()
18:59:24.198 INFO  DAGScheduler - waiting: HashSet(ResultStage 757)
18:59:24.199 INFO  DAGScheduler - failed: HashSet()
18:59:24.199 INFO  DAGScheduler - Submitting ResultStage 757 (MapPartitionsRDD[3555] at mapToPair at BamSink.java:91), which has no missing parents
18:59:24.205 INFO  MemoryStore - Block broadcast_1398 stored as values in memory (estimated size 163.7 KiB, free 1896.0 MiB)
18:59:24.206 INFO  MemoryStore - Block broadcast_1398_piece0 stored as bytes in memory (estimated size 73.9 KiB, free 1896.0 MiB)
18:59:24.206 INFO  BlockManagerInfo - Added broadcast_1398_piece0 in memory on localhost:40133 (size: 73.9 KiB, free: 1918.1 MiB)
18:59:24.206 INFO  SparkContext - Created broadcast 1398 from broadcast at DAGScheduler.scala:1580
18:59:24.206 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:59:24.206 INFO  TaskSchedulerImpl - Adding task set 757.0 with 1 tasks resource profile 0
18:59:24.207 INFO  TaskSetManager - Starting task 0.0 in stage 757.0 (TID 691) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:24.207 INFO  Executor - Running task 0.0 in stage 757.0 (TID 691)
18:59:24.211 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:59:24.211 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:24.213 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:59:24.213 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:24.214 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:24.214 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
18:59:24.214 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:24.214 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:24.235 INFO  FileOutputCommitter - Saved output of task 'attempt_202505191859247427564598392303875_3555_r_000000_0' to file:/tmp/local12542579939630629552/markdups17250150486765507721.bam.parts/_temporary/0/task_202505191859247427564598392303875_3555_r_000000
18:59:24.235 INFO  SparkHadoopMapRedUtil - attempt_202505191859247427564598392303875_3555_r_000000_0: Committed. Elapsed time: 0 ms.
18:59:24.235 INFO  Executor - Finished task 0.0 in stage 757.0 (TID 691). 1858 bytes result sent to driver
18:59:24.236 INFO  TaskSetManager - Finished task 0.0 in stage 757.0 (TID 691) in 29 ms on localhost (executor driver) (1/1)
18:59:24.236 INFO  TaskSchedulerImpl - Removed TaskSet 757.0, whose tasks have all completed, from pool 
18:59:24.236 INFO  DAGScheduler - ResultStage 757 (runJob at SparkHadoopWriter.scala:83) finished in 0.037 s
18:59:24.236 INFO  DAGScheduler - Job 428 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:24.236 INFO  TaskSchedulerImpl - Killing all running tasks in stage 757: Stage finished
18:59:24.236 INFO  DAGScheduler - Job 428 finished: runJob at SparkHadoopWriter.scala:83, took 0.047438 s
18:59:24.236 INFO  SparkHadoopWriter - Start to commit write Job job_202505191859247427564598392303875_3555.
18:59:24.241 INFO  SparkHadoopWriter - Write Job job_202505191859247427564598392303875_3555 committed. Elapsed time: 4 ms.
18:59:24.252 INFO  HadoopFileSystemWrapper - Concatenating 3 parts to /tmp/local12542579939630629552/markdups17250150486765507721.bam
18:59:24.255 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/local12542579939630629552/markdups17250150486765507721.bam done
18:59:24.256 INFO  IndexFileMerger - Merging .sbi files in temp directory /tmp/local12542579939630629552/markdups17250150486765507721.bam.parts/ to /tmp/local12542579939630629552/markdups17250150486765507721.bam.sbi
18:59:24.260 INFO  IndexFileMerger - Done merging .sbi files
18:59:24.260 INFO  IndexFileMerger - Merging .bai files in temp directory /tmp/local12542579939630629552/markdups17250150486765507721.bam.parts/ to /tmp/local12542579939630629552/markdups17250150486765507721.bam.bai
18:59:24.265 INFO  IndexFileMerger - Done merging .bai files
18:59:24.265 INFO  MarkDuplicatesSpark - Shutting down engine
[May 19, 2025 at 6:59:24 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:24 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:24 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:25 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:25 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:26 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:26 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:27 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:28 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:29 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:29 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:30 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:30 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:30 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:32 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:33 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:33 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:33 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:34 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:34 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:35 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:36 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:37 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:37 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:38 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:38 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:38 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:39 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:40 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:41 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:41 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:42 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:42 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:43 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:43 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:44 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:45 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:46 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:47 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:49 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:49 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
18:59:49.537 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:49.537 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:59:49.537 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:59:49.537 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:59:49.537 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:59:49.537 INFO  MarkDuplicatesSpark - Start Date/Time: May 19, 2025 at 6:59:49 PM UTC
18:59:49.537 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:49.537 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:49.537 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:59:49.537 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:59:49.537 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:59:49.537 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:59:49.537 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:59:49.537 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:59:49.537 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:59:49.537 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:59:49.538 INFO  MarkDuplicatesSpark - Initializing engine
18:59:49.538 INFO  MarkDuplicatesSpark - Done initializing engine
18:59:49.538 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:59:49.540 INFO  MemoryStore - Block broadcast_1975 stored as values in memory (estimated size 306.3 KiB, free 1913.2 MiB)
18:59:49.547 INFO  MemoryStore - Block broadcast_1975_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1913.1 MiB)
18:59:49.547 INFO  BlockManagerInfo - Added broadcast_1975_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1919.3 MiB)
18:59:49.547 INFO  SparkContext - Created broadcast 1975 from newAPIHadoopFile at PathSplitSource.java:96
18:59:49.568 INFO  MemoryStore - Block broadcast_1976 stored as values in memory (estimated size 306.3 KiB, free 1912.8 MiB)
18:59:49.574 INFO  MemoryStore - Block broadcast_1976_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1912.7 MiB)
18:59:49.574 INFO  BlockManagerInfo - Added broadcast_1976_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1919.3 MiB)
18:59:49.574 INFO  SparkContext - Created broadcast 1976 from newAPIHadoopFile at PathSplitSource.java:96
18:59:49.607 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:59:49.608 INFO  FileInputFormat - Total input files to process : 1
18:59:49.608 INFO  DAGScheduler - Registering RDD 5447 (mapToPair at SparkUtils.java:161) as input to shuffle 300
18:59:49.608 INFO  DAGScheduler - Got job 559 (collect at SparkUtils.java:205) with 1 output partitions
18:59:49.608 INFO  DAGScheduler - Final stage: ResultStage 1219 (collect at SparkUtils.java:205)
18:59:49.608 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1218)
18:59:49.608 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1218)
18:59:49.609 INFO  DAGScheduler - Submitting ShuffleMapStage 1218 (MapPartitionsRDD[5447] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:49.632 INFO  MemoryStore - Block broadcast_1977 stored as values in memory (estimated size 493.8 KiB, free 1912.3 MiB)
18:59:49.635 INFO  MemoryStore - Block broadcast_1977_piece0 stored as bytes in memory (estimated size 210.1 KiB, free 1912.1 MiB)
18:59:49.635 INFO  BlockManagerInfo - Added broadcast_1977_piece0 in memory on localhost:40133 (size: 210.1 KiB, free: 1919.0 MiB)
18:59:49.635 INFO  SparkContext - Created broadcast 1977 from broadcast at DAGScheduler.scala:1580
18:59:49.635 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:59:49.635 INFO  TaskSchedulerImpl - Adding task set 1218.0 with 1 tasks resource profile 0
18:59:49.636 INFO  TaskSetManager - Starting task 0.0 in stage 1218.0 (TID 1062) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9758 bytes) 
18:59:49.636 INFO  Executor - Running task 0.0 in stage 1218.0 (TID 1062)
18:59:49.669 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:59:49.674 INFO  Executor - Finished task 0.0 in stage 1218.0 (TID 1062). 1148 bytes result sent to driver
18:59:49.674 INFO  TaskSetManager - Finished task 0.0 in stage 1218.0 (TID 1062) in 39 ms on localhost (executor driver) (1/1)
18:59:49.674 INFO  TaskSchedulerImpl - Removed TaskSet 1218.0, whose tasks have all completed, from pool 
18:59:49.675 INFO  DAGScheduler - ShuffleMapStage 1218 (mapToPair at SparkUtils.java:161) finished in 0.066 s
18:59:49.675 INFO  DAGScheduler - looking for newly runnable stages
18:59:49.675 INFO  DAGScheduler - running: HashSet()
18:59:49.675 INFO  DAGScheduler - waiting: HashSet(ResultStage 1219)
18:59:49.675 INFO  DAGScheduler - failed: HashSet()
18:59:49.675 INFO  DAGScheduler - Submitting ResultStage 1219 (MapPartitionsRDD[5450] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:59:49.676 INFO  MemoryStore - Block broadcast_1978 stored as values in memory (estimated size 7.4 KiB, free 1912.0 MiB)
18:59:49.676 INFO  MemoryStore - Block broadcast_1978_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1912.0 MiB)
18:59:49.676 INFO  BlockManagerInfo - Added broadcast_1978_piece0 in memory on localhost:40133 (size: 4.1 KiB, free: 1919.0 MiB)
18:59:49.676 INFO  SparkContext - Created broadcast 1978 from broadcast at DAGScheduler.scala:1580
18:59:49.677 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:59:49.677 INFO  TaskSchedulerImpl - Adding task set 1219.0 with 1 tasks resource profile 0
18:59:49.677 INFO  TaskSetManager - Starting task 0.0 in stage 1219.0 (TID 1063) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:49.677 INFO  Executor - Running task 0.0 in stage 1219.0 (TID 1063)
18:59:49.678 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:59:49.678 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.681 INFO  Executor - Finished task 0.0 in stage 1219.0 (TID 1063). 2329 bytes result sent to driver
18:59:49.681 INFO  TaskSetManager - Finished task 0.0 in stage 1219.0 (TID 1063) in 4 ms on localhost (executor driver) (1/1)
18:59:49.681 INFO  TaskSchedulerImpl - Removed TaskSet 1219.0, whose tasks have all completed, from pool 
18:59:49.681 INFO  DAGScheduler - ResultStage 1219 (collect at SparkUtils.java:205) finished in 0.006 s
18:59:49.681 INFO  DAGScheduler - Job 559 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:49.681 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1219: Stage finished
18:59:49.681 INFO  DAGScheduler - Job 559 finished: collect at SparkUtils.java:205, took 0.074175 s
18:59:49.686 INFO  MemoryStore - Block broadcast_1979 stored as values in memory (estimated size 7.8 KiB, free 1912.0 MiB)
18:59:49.686 INFO  MemoryStore - Block broadcast_1979_piece0 stored as bytes in memory (estimated size 540.0 B, free 1912.0 MiB)
18:59:49.686 INFO  BlockManagerInfo - Added broadcast_1979_piece0 in memory on localhost:40133 (size: 540.0 B, free: 1919.0 MiB)
18:59:49.686 INFO  SparkContext - Created broadcast 1979 from broadcast at MarkDuplicatesSparkUtils.java:126
18:59:49.687 INFO  MemoryStore - Block broadcast_1980 stored as values in memory (estimated size 2.6 KiB, free 1912.0 MiB)
18:59:49.687 INFO  MemoryStore - Block broadcast_1980_piece0 stored as bytes in memory (estimated size 209.0 B, free 1912.0 MiB)
18:59:49.687 INFO  BlockManagerInfo - Added broadcast_1980_piece0 in memory on localhost:40133 (size: 209.0 B, free: 1919.0 MiB)
18:59:49.687 INFO  SparkContext - Created broadcast 1980 from broadcast at MarkDuplicatesSparkUtils.java:127
18:59:49.701 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:59:49.702 INFO  DAGScheduler - Registering RDD 5459 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 303
18:59:49.702 INFO  DAGScheduler - Registering RDD 5463 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 302
18:59:49.702 INFO  DAGScheduler - Registering RDD 5467 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 301
18:59:49.702 INFO  DAGScheduler - Got job 560 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:59:49.702 INFO  DAGScheduler - Final stage: ResultStage 1224 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:59:49.702 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1223)
18:59:49.702 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1223)
18:59:49.703 INFO  DAGScheduler - Submitting ShuffleMapStage 1221 (MapPartitionsRDD[5459] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:59:49.704 INFO  MemoryStore - Block broadcast_1981 stored as values in memory (estimated size 57.6 KiB, free 1912.0 MiB)
18:59:49.705 INFO  MemoryStore - Block broadcast_1981_piece0 stored as bytes in memory (estimated size 19.8 KiB, free 1912.0 MiB)
18:59:49.705 INFO  BlockManagerInfo - Added broadcast_1981_piece0 in memory on localhost:40133 (size: 19.8 KiB, free: 1919.0 MiB)
18:59:49.705 INFO  SparkContext - Created broadcast 1981 from broadcast at DAGScheduler.scala:1580
18:59:49.705 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:59:49.705 INFO  TaskSchedulerImpl - Adding task set 1221.0 with 1 tasks resource profile 0
18:59:49.706 INFO  TaskSetManager - Starting task 0.0 in stage 1221.0 (TID 1064) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:59:49.706 INFO  Executor - Running task 0.0 in stage 1221.0 (TID 1064)
18:59:49.709 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:59:49.709 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.714 INFO  Executor - Finished task 0.0 in stage 1221.0 (TID 1064). 1922 bytes result sent to driver
18:59:49.715 INFO  TaskSetManager - Finished task 0.0 in stage 1221.0 (TID 1064) in 9 ms on localhost (executor driver) (1/1)
18:59:49.715 INFO  TaskSchedulerImpl - Removed TaskSet 1221.0, whose tasks have all completed, from pool 
18:59:49.715 INFO  DAGScheduler - ShuffleMapStage 1221 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.012 s
18:59:49.715 INFO  DAGScheduler - looking for newly runnable stages
18:59:49.715 INFO  DAGScheduler - running: HashSet()
18:59:49.715 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1222, ShuffleMapStage 1223, ResultStage 1224)
18:59:49.715 INFO  DAGScheduler - failed: HashSet()
18:59:49.716 INFO  DAGScheduler - Submitting ShuffleMapStage 1222 (MapPartitionsRDD[5463] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:59:49.717 INFO  MemoryStore - Block broadcast_1982 stored as values in memory (estimated size 61.7 KiB, free 1911.9 MiB)
18:59:49.718 INFO  MemoryStore - Block broadcast_1982_piece0 stored as bytes in memory (estimated size 22.0 KiB, free 1911.9 MiB)
18:59:49.718 INFO  BlockManagerInfo - Added broadcast_1982_piece0 in memory on localhost:40133 (size: 22.0 KiB, free: 1919.0 MiB)
18:59:49.718 INFO  SparkContext - Created broadcast 1982 from broadcast at DAGScheduler.scala:1580
18:59:49.718 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:59:49.718 INFO  TaskSchedulerImpl - Adding task set 1222.0 with 1 tasks resource profile 0
18:59:49.719 INFO  TaskSetManager - Starting task 0.0 in stage 1222.0 (TID 1065) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:59:49.719 INFO  Executor - Running task 0.0 in stage 1222.0 (TID 1065)
18:59:49.721 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:59:49.721 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.727 INFO  Executor - Finished task 0.0 in stage 1222.0 (TID 1065). 1922 bytes result sent to driver
18:59:49.728 INFO  TaskSetManager - Finished task 0.0 in stage 1222.0 (TID 1065) in 9 ms on localhost (executor driver) (1/1)
18:59:49.728 INFO  TaskSchedulerImpl - Removed TaskSet 1222.0, whose tasks have all completed, from pool 
18:59:49.728 INFO  DAGScheduler - ShuffleMapStage 1222 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.012 s
18:59:49.728 INFO  DAGScheduler - looking for newly runnable stages
18:59:49.728 INFO  DAGScheduler - running: HashSet()
18:59:49.728 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1223, ResultStage 1224)
18:59:49.728 INFO  DAGScheduler - failed: HashSet()
18:59:49.728 INFO  DAGScheduler - Submitting ShuffleMapStage 1223 (MapPartitionsRDD[5467] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:59:49.729 INFO  MemoryStore - Block broadcast_1983 stored as values in memory (estimated size 52.4 KiB, free 1911.8 MiB)
18:59:49.730 INFO  MemoryStore - Block broadcast_1983_piece0 stored as bytes in memory (estimated size 17.3 KiB, free 1911.8 MiB)
18:59:49.730 INFO  BlockManagerInfo - Added broadcast_1983_piece0 in memory on localhost:40133 (size: 17.3 KiB, free: 1919.0 MiB)
18:59:49.730 INFO  SparkContext - Created broadcast 1983 from broadcast at DAGScheduler.scala:1580
18:59:49.730 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:59:49.730 INFO  TaskSchedulerImpl - Adding task set 1223.0 with 1 tasks resource profile 0
18:59:49.731 INFO  TaskSetManager - Starting task 0.0 in stage 1223.0 (TID 1066) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:49.731 INFO  Executor - Running task 0.0 in stage 1223.0 (TID 1066)
18:59:49.732 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:59:49.732 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.735 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:59:49.735 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.737 INFO  Executor - Finished task 0.0 in stage 1223.0 (TID 1066). 1922 bytes result sent to driver
18:59:49.737 INFO  TaskSetManager - Finished task 0.0 in stage 1223.0 (TID 1066) in 7 ms on localhost (executor driver) (1/1)
18:59:49.738 INFO  TaskSchedulerImpl - Removed TaskSet 1223.0, whose tasks have all completed, from pool 
18:59:49.738 INFO  DAGScheduler - ShuffleMapStage 1223 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.010 s
18:59:49.738 INFO  DAGScheduler - looking for newly runnable stages
18:59:49.738 INFO  DAGScheduler - running: HashSet()
18:59:49.738 INFO  DAGScheduler - waiting: HashSet(ResultStage 1224)
18:59:49.738 INFO  DAGScheduler - failed: HashSet()
18:59:49.738 INFO  DAGScheduler - Submitting ResultStage 1224 (MapPartitionsRDD[5469] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:59:49.739 INFO  MemoryStore - Block broadcast_1984 stored as values in memory (estimated size 53.6 KiB, free 1911.8 MiB)
18:59:49.739 INFO  MemoryStore - Block broadcast_1984_piece0 stored as bytes in memory (estimated size 18.0 KiB, free 1911.7 MiB)
18:59:49.740 INFO  BlockManagerInfo - Added broadcast_1984_piece0 in memory on localhost:40133 (size: 18.0 KiB, free: 1919.0 MiB)
18:59:49.740 INFO  SparkContext - Created broadcast 1984 from broadcast at DAGScheduler.scala:1580
18:59:49.740 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:59:49.740 INFO  TaskSchedulerImpl - Adding task set 1224.0 with 1 tasks resource profile 0
18:59:49.740 INFO  TaskSetManager - Starting task 0.0 in stage 1224.0 (TID 1067) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:49.740 INFO  Executor - Running task 0.0 in stage 1224.0 (TID 1067)
18:59:49.742 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:59:49.742 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.743 INFO  Executor - Finished task 0.0 in stage 1224.0 (TID 1067). 2371 bytes result sent to driver
18:59:49.744 INFO  TaskSetManager - Finished task 0.0 in stage 1224.0 (TID 1067) in 4 ms on localhost (executor driver) (1/1)
18:59:49.744 INFO  TaskSchedulerImpl - Removed TaskSet 1224.0, whose tasks have all completed, from pool 
18:59:49.744 INFO  DAGScheduler - ResultStage 1224 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.006 s
18:59:49.744 INFO  DAGScheduler - Job 560 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:49.744 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1224: Stage finished
18:59:49.744 INFO  DAGScheduler - Job 560 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.042459 s
18:59:49.756 INFO  MemoryStore - Block broadcast_1985 stored as values in memory (estimated size 179.4 KiB, free 1911.6 MiB)
18:59:49.757 INFO  MemoryStore - Block broadcast_1985_piece0 stored as bytes in memory (estimated size 7.9 KiB, free 1911.6 MiB)
18:59:49.757 INFO  BlockManagerInfo - Added broadcast_1985_piece0 in memory on localhost:40133 (size: 7.9 KiB, free: 1919.0 MiB)
18:59:49.757 INFO  SparkContext - Created broadcast 1985 from broadcast at ReadsSparkSink.java:133
18:59:49.761 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:59:49.761 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:49.761 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:49.778 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:59:49.778 INFO  DAGScheduler - Registering RDD 5471 (mapToPair at SparkUtils.java:161) as input to shuffle 304
18:59:49.778 INFO  DAGScheduler - Got job 561 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:59:49.778 INFO  DAGScheduler - Final stage: ResultStage 1229 (runJob at SparkHadoopWriter.scala:83)
18:59:49.778 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1228)
18:59:49.778 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1228)
18:59:49.779 INFO  DAGScheduler - Submitting ShuffleMapStage 1228 (MapPartitionsRDD[5471] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:49.780 INFO  MemoryStore - Block broadcast_1986 stored as values in memory (estimated size 51.5 KiB, free 1911.5 MiB)
18:59:49.780 INFO  MemoryStore - Block broadcast_1986_piece0 stored as bytes in memory (estimated size 16.8 KiB, free 1911.5 MiB)
18:59:49.780 INFO  BlockManagerInfo - Added broadcast_1986_piece0 in memory on localhost:40133 (size: 16.8 KiB, free: 1918.9 MiB)
18:59:49.780 INFO  SparkContext - Created broadcast 1986 from broadcast at DAGScheduler.scala:1580
18:59:49.781 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:59:49.781 INFO  TaskSchedulerImpl - Adding task set 1228.0 with 1 tasks resource profile 0
18:59:49.781 INFO  TaskSetManager - Starting task 0.0 in stage 1228.0 (TID 1068) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:49.781 INFO  Executor - Running task 0.0 in stage 1228.0 (TID 1068)
18:59:49.783 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:59:49.783 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.787 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:59:49.787 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.788 INFO  Executor - Finished task 0.0 in stage 1228.0 (TID 1068). 1922 bytes result sent to driver
18:59:49.789 INFO  TaskSetManager - Finished task 0.0 in stage 1228.0 (TID 1068) in 8 ms on localhost (executor driver) (1/1)
18:59:49.789 INFO  TaskSchedulerImpl - Removed TaskSet 1228.0, whose tasks have all completed, from pool 
18:59:49.789 INFO  DAGScheduler - ShuffleMapStage 1228 (mapToPair at SparkUtils.java:161) finished in 0.010 s
18:59:49.789 INFO  DAGScheduler - looking for newly runnable stages
18:59:49.789 INFO  DAGScheduler - running: HashSet()
18:59:49.789 INFO  DAGScheduler - waiting: HashSet(ResultStage 1229)
18:59:49.789 INFO  DAGScheduler - failed: HashSet()
18:59:49.789 INFO  DAGScheduler - Submitting ResultStage 1229 (MapPartitionsRDD[5477] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:59:49.796 INFO  MemoryStore - Block broadcast_1987 stored as values in memory (estimated size 196.7 KiB, free 1911.3 MiB)
18:59:49.797 INFO  MemoryStore - Block broadcast_1987_piece0 stored as bytes in memory (estimated size 80.9 KiB, free 1911.2 MiB)
18:59:49.797 INFO  BlockManagerInfo - Added broadcast_1987_piece0 in memory on localhost:40133 (size: 80.9 KiB, free: 1918.9 MiB)
18:59:49.797 INFO  SparkContext - Created broadcast 1987 from broadcast at DAGScheduler.scala:1580
18:59:49.798 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:59:49.798 INFO  TaskSchedulerImpl - Adding task set 1229.0 with 1 tasks resource profile 0
18:59:49.798 INFO  TaskSetManager - Starting task 0.0 in stage 1229.0 (TID 1069) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:49.798 INFO  Executor - Running task 0.0 in stage 1229.0 (TID 1069)
18:59:49.802 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:59:49.802 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.804 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:59:49.804 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:49.804 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:49.816 INFO  FileOutputCommitter - Saved output of task 'attempt_202505191859497169317973656029875_5477_m_000000_0' to file:/tmp/MarkDups9490753933218824053/MarkDups.sam.parts/_temporary/0/task_202505191859497169317973656029875_5477_m_000000
18:59:49.816 INFO  SparkHadoopMapRedUtil - attempt_202505191859497169317973656029875_5477_m_000000_0: Committed. Elapsed time: 0 ms.
18:59:49.816 INFO  Executor - Finished task 0.0 in stage 1229.0 (TID 1069). 1858 bytes result sent to driver
18:59:49.816 INFO  TaskSetManager - Finished task 0.0 in stage 1229.0 (TID 1069) in 18 ms on localhost (executor driver) (1/1)
18:59:49.816 INFO  TaskSchedulerImpl - Removed TaskSet 1229.0, whose tasks have all completed, from pool 
18:59:49.816 INFO  DAGScheduler - ResultStage 1229 (runJob at SparkHadoopWriter.scala:83) finished in 0.027 s
18:59:49.817 INFO  DAGScheduler - Job 561 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:49.817 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1229: Stage finished
18:59:49.817 INFO  DAGScheduler - Job 561 finished: runJob at SparkHadoopWriter.scala:83, took 0.038808 s
18:59:49.817 INFO  SparkHadoopWriter - Start to commit write Job job_202505191859497169317973656029875_5477.
18:59:49.821 INFO  SparkHadoopWriter - Write Job job_202505191859497169317973656029875_5477 committed. Elapsed time: 4 ms.
18:59:49.829 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups9490753933218824053/MarkDups.sam
18:59:49.832 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups9490753933218824053/MarkDups.sam done
18:59:49.832 INFO  MarkDuplicatesSpark - Shutting down engine
[May 19, 2025 at 6:59:49 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
18:59:49.838 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:49.838 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:59:49.838 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:59:49.838 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:59:49.838 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:59:49.838 INFO  MarkDuplicatesSpark - Start Date/Time: May 19, 2025 at 6:59:49 PM UTC
18:59:49.838 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:49.838 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:49.838 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:59:49.838 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:59:49.838 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:59:49.838 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:59:49.838 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:59:49.839 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:59:49.839 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:59:49.839 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:59:49.839 INFO  MarkDuplicatesSpark - Initializing engine
18:59:49.839 INFO  MarkDuplicatesSpark - Done initializing engine
18:59:49.839 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:59:49.841 INFO  MemoryStore - Block broadcast_1988 stored as values in memory (estimated size 306.3 KiB, free 1910.9 MiB)
18:59:49.847 INFO  MemoryStore - Block broadcast_1988_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1910.9 MiB)
18:59:49.847 INFO  BlockManagerInfo - Added broadcast_1988_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1918.8 MiB)
18:59:49.848 INFO  SparkContext - Created broadcast 1988 from newAPIHadoopFile at PathSplitSource.java:96
18:59:49.868 INFO  MemoryStore - Block broadcast_1989 stored as values in memory (estimated size 306.3 KiB, free 1910.6 MiB)
18:59:49.874 INFO  MemoryStore - Block broadcast_1989_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1910.5 MiB)
18:59:49.874 INFO  BlockManagerInfo - Added broadcast_1989_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1918.7 MiB)
18:59:49.874 INFO  SparkContext - Created broadcast 1989 from newAPIHadoopFile at PathSplitSource.java:96
18:59:49.906 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:59:49.907 INFO  FileInputFormat - Total input files to process : 1
18:59:49.907 INFO  DAGScheduler - Registering RDD 5491 (mapToPair at SparkUtils.java:161) as input to shuffle 305
18:59:49.907 INFO  DAGScheduler - Got job 562 (collect at SparkUtils.java:205) with 1 output partitions
18:59:49.907 INFO  DAGScheduler - Final stage: ResultStage 1231 (collect at SparkUtils.java:205)
18:59:49.907 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1230)
18:59:49.907 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1230)
18:59:49.908 INFO  DAGScheduler - Submitting ShuffleMapStage 1230 (MapPartitionsRDD[5491] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:49.924 INFO  MemoryStore - Block broadcast_1990 stored as values in memory (estimated size 457.4 KiB, free 1910.0 MiB)
18:59:49.926 INFO  MemoryStore - Block broadcast_1990_piece0 stored as bytes in memory (estimated size 201.1 KiB, free 1909.9 MiB)
18:59:49.927 INFO  BlockManagerInfo - Added broadcast_1990_piece0 in memory on localhost:40133 (size: 201.1 KiB, free: 1918.5 MiB)
18:59:49.927 INFO  SparkContext - Created broadcast 1990 from broadcast at DAGScheduler.scala:1580
18:59:49.927 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:59:49.927 INFO  TaskSchedulerImpl - Adding task set 1230.0 with 1 tasks resource profile 0
18:59:49.927 INFO  TaskSetManager - Starting task 0.0 in stage 1230.0 (TID 1070) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9738 bytes) 
18:59:49.927 INFO  Executor - Running task 0.0 in stage 1230.0 (TID 1070)
18:59:49.957 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:59:49.960 INFO  Executor - Finished task 0.0 in stage 1230.0 (TID 1070). 1148 bytes result sent to driver
18:59:49.961 INFO  TaskSetManager - Finished task 0.0 in stage 1230.0 (TID 1070) in 34 ms on localhost (executor driver) (1/1)
18:59:49.961 INFO  TaskSchedulerImpl - Removed TaskSet 1230.0, whose tasks have all completed, from pool 
18:59:49.961 INFO  DAGScheduler - ShuffleMapStage 1230 (mapToPair at SparkUtils.java:161) finished in 0.053 s
18:59:49.961 INFO  DAGScheduler - looking for newly runnable stages
18:59:49.961 INFO  DAGScheduler - running: HashSet()
18:59:49.961 INFO  DAGScheduler - waiting: HashSet(ResultStage 1231)
18:59:49.961 INFO  DAGScheduler - failed: HashSet()
18:59:49.961 INFO  DAGScheduler - Submitting ResultStage 1231 (MapPartitionsRDD[5494] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:59:49.961 INFO  MemoryStore - Block broadcast_1991 stored as values in memory (estimated size 7.4 KiB, free 1909.8 MiB)
18:59:49.962 INFO  MemoryStore - Block broadcast_1991_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1909.8 MiB)
18:59:49.962 INFO  BlockManagerInfo - Added broadcast_1991_piece0 in memory on localhost:40133 (size: 4.1 KiB, free: 1918.5 MiB)
18:59:49.962 INFO  SparkContext - Created broadcast 1991 from broadcast at DAGScheduler.scala:1580
18:59:49.962 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:59:49.962 INFO  TaskSchedulerImpl - Adding task set 1231.0 with 1 tasks resource profile 0
18:59:49.963 INFO  TaskSetManager - Starting task 0.0 in stage 1231.0 (TID 1071) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:49.963 INFO  Executor - Running task 0.0 in stage 1231.0 (TID 1071)
18:59:49.964 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:59:49.964 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.965 INFO  Executor - Finished task 0.0 in stage 1231.0 (TID 1071). 2269 bytes result sent to driver
18:59:49.965 INFO  TaskSetManager - Finished task 0.0 in stage 1231.0 (TID 1071) in 3 ms on localhost (executor driver) (1/1)
18:59:49.965 INFO  TaskSchedulerImpl - Removed TaskSet 1231.0, whose tasks have all completed, from pool 
18:59:49.965 INFO  DAGScheduler - ResultStage 1231 (collect at SparkUtils.java:205) finished in 0.004 s
18:59:49.965 INFO  DAGScheduler - Job 562 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:49.965 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1231: Stage finished
18:59:49.965 INFO  DAGScheduler - Job 562 finished: collect at SparkUtils.java:205, took 0.058941 s
18:59:49.969 INFO  MemoryStore - Block broadcast_1992 stored as values in memory (estimated size 136.0 B, free 1909.8 MiB)
18:59:49.970 INFO  MemoryStore - Block broadcast_1992_piece0 stored as bytes in memory (estimated size 24.0 B, free 1909.8 MiB)
18:59:49.970 INFO  BlockManagerInfo - Added broadcast_1992_piece0 in memory on localhost:40133 (size: 24.0 B, free: 1918.5 MiB)
18:59:49.970 INFO  SparkContext - Created broadcast 1992 from broadcast at MarkDuplicatesSparkUtils.java:126
18:59:49.970 INFO  MemoryStore - Block broadcast_1993 stored as values in memory (estimated size 136.0 B, free 1909.8 MiB)
18:59:49.970 INFO  MemoryStore - Block broadcast_1993_piece0 stored as bytes in memory (estimated size 21.0 B, free 1909.8 MiB)
18:59:49.970 INFO  BlockManagerInfo - Added broadcast_1993_piece0 in memory on localhost:40133 (size: 21.0 B, free: 1918.5 MiB)
18:59:49.971 INFO  SparkContext - Created broadcast 1993 from broadcast at MarkDuplicatesSparkUtils.java:127
18:59:49.982 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:59:49.983 INFO  DAGScheduler - Registering RDD 5503 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 308
18:59:49.983 INFO  DAGScheduler - Registering RDD 5507 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 307
18:59:49.983 INFO  DAGScheduler - Registering RDD 5511 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 306
18:59:49.983 INFO  DAGScheduler - Got job 563 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:59:49.983 INFO  DAGScheduler - Final stage: ResultStage 1236 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:59:49.983 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1235)
18:59:49.983 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1235)
18:59:49.983 INFO  DAGScheduler - Submitting ShuffleMapStage 1233 (MapPartitionsRDD[5503] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:59:49.984 INFO  MemoryStore - Block broadcast_1994 stored as values in memory (estimated size 21.1 KiB, free 1909.8 MiB)
18:59:49.984 INFO  MemoryStore - Block broadcast_1994_piece0 stored as bytes in memory (estimated size 10.9 KiB, free 1909.8 MiB)
18:59:49.984 INFO  BlockManagerInfo - Added broadcast_1994_piece0 in memory on localhost:40133 (size: 10.9 KiB, free: 1918.5 MiB)
18:59:49.984 INFO  SparkContext - Created broadcast 1994 from broadcast at DAGScheduler.scala:1580
18:59:49.984 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:59:49.984 INFO  TaskSchedulerImpl - Adding task set 1233.0 with 1 tasks resource profile 0
18:59:49.985 INFO  TaskSetManager - Starting task 0.0 in stage 1233.0 (TID 1072) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:59:49.985 INFO  Executor - Running task 0.0 in stage 1233.0 (TID 1072)
18:59:49.986 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:59:49.987 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.988 INFO  Executor - Finished task 0.0 in stage 1233.0 (TID 1072). 1922 bytes result sent to driver
18:59:49.989 INFO  TaskSetManager - Finished task 0.0 in stage 1233.0 (TID 1072) in 4 ms on localhost (executor driver) (1/1)
18:59:49.989 INFO  TaskSchedulerImpl - Removed TaskSet 1233.0, whose tasks have all completed, from pool 
18:59:49.989 INFO  DAGScheduler - ShuffleMapStage 1233 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.006 s
18:59:49.989 INFO  DAGScheduler - looking for newly runnable stages
18:59:49.989 INFO  DAGScheduler - running: HashSet()
18:59:49.989 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1234, ShuffleMapStage 1235, ResultStage 1236)
18:59:49.989 INFO  DAGScheduler - failed: HashSet()
18:59:49.989 INFO  DAGScheduler - Submitting ShuffleMapStage 1234 (MapPartitionsRDD[5507] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:59:49.990 INFO  MemoryStore - Block broadcast_1995 stored as values in memory (estimated size 25.2 KiB, free 1909.8 MiB)
18:59:49.990 INFO  MemoryStore - Block broadcast_1995_piece0 stored as bytes in memory (estimated size 13.1 KiB, free 1909.8 MiB)
18:59:49.990 INFO  BlockManagerInfo - Added broadcast_1995_piece0 in memory on localhost:40133 (size: 13.1 KiB, free: 1918.5 MiB)
18:59:49.990 INFO  SparkContext - Created broadcast 1995 from broadcast at DAGScheduler.scala:1580
18:59:49.990 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:59:49.990 INFO  TaskSchedulerImpl - Adding task set 1234.0 with 1 tasks resource profile 0
18:59:49.991 INFO  TaskSetManager - Starting task 0.0 in stage 1234.0 (TID 1073) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:59:49.991 INFO  Executor - Running task 0.0 in stage 1234.0 (TID 1073)
18:59:49.992 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:59:49.992 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:49.995 INFO  Executor - Finished task 0.0 in stage 1234.0 (TID 1073). 1879 bytes result sent to driver
18:59:49.996 INFO  TaskSetManager - Finished task 0.0 in stage 1234.0 (TID 1073) in 5 ms on localhost (executor driver) (1/1)
18:59:49.996 INFO  TaskSchedulerImpl - Removed TaskSet 1234.0, whose tasks have all completed, from pool 
18:59:49.996 INFO  DAGScheduler - ShuffleMapStage 1234 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.007 s
18:59:49.996 INFO  DAGScheduler - looking for newly runnable stages
18:59:49.996 INFO  DAGScheduler - running: HashSet()
18:59:49.996 INFO  DAGScheduler - waiting: HashSet(ShuffleMapStage 1235, ResultStage 1236)
18:59:49.996 INFO  DAGScheduler - failed: HashSet()
18:59:49.996 INFO  DAGScheduler - Submitting ShuffleMapStage 1235 (MapPartitionsRDD[5511] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:59:49.996 INFO  MemoryStore - Block broadcast_1996 stored as values in memory (estimated size 15.9 KiB, free 1909.8 MiB)
18:59:49.997 INFO  MemoryStore - Block broadcast_1996_piece0 stored as bytes in memory (estimated size 8.3 KiB, free 1909.7 MiB)
18:59:49.997 INFO  BlockManagerInfo - Added broadcast_1996_piece0 in memory on localhost:40133 (size: 8.3 KiB, free: 1918.5 MiB)
18:59:49.997 INFO  SparkContext - Created broadcast 1996 from broadcast at DAGScheduler.scala:1580
18:59:49.997 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:59:49.997 INFO  TaskSchedulerImpl - Adding task set 1235.0 with 1 tasks resource profile 0
18:59:49.998 INFO  TaskSetManager - Starting task 0.0 in stage 1235.0 (TID 1074) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:49.998 INFO  Executor - Running task 0.0 in stage 1235.0 (TID 1074)
18:59:49.999 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:59:49.999 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.000 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:59:50.000 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.001 INFO  Executor - Finished task 0.0 in stage 1235.0 (TID 1074). 1879 bytes result sent to driver
18:59:50.001 INFO  TaskSetManager - Finished task 0.0 in stage 1235.0 (TID 1074) in 4 ms on localhost (executor driver) (1/1)
18:59:50.001 INFO  TaskSchedulerImpl - Removed TaskSet 1235.0, whose tasks have all completed, from pool 
18:59:50.002 INFO  DAGScheduler - ShuffleMapStage 1235 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.006 s
18:59:50.002 INFO  DAGScheduler - looking for newly runnable stages
18:59:50.002 INFO  DAGScheduler - running: HashSet()
18:59:50.002 INFO  DAGScheduler - waiting: HashSet(ResultStage 1236)
18:59:50.002 INFO  DAGScheduler - failed: HashSet()
18:59:50.002 INFO  DAGScheduler - Submitting ResultStage 1236 (MapPartitionsRDD[5513] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:59:50.002 INFO  MemoryStore - Block broadcast_1997 stored as values in memory (estimated size 17.1 KiB, free 1909.7 MiB)
18:59:50.003 INFO  MemoryStore - Block broadcast_1997_piece0 stored as bytes in memory (estimated size 9.0 KiB, free 1909.7 MiB)
18:59:50.003 INFO  BlockManagerInfo - Added broadcast_1997_piece0 in memory on localhost:40133 (size: 9.0 KiB, free: 1918.5 MiB)
18:59:50.003 INFO  SparkContext - Created broadcast 1997 from broadcast at DAGScheduler.scala:1580
18:59:50.003 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:59:50.003 INFO  TaskSchedulerImpl - Adding task set 1236.0 with 1 tasks resource profile 0
18:59:50.004 INFO  TaskSetManager - Starting task 0.0 in stage 1236.0 (TID 1075) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:50.004 INFO  Executor - Running task 0.0 in stage 1236.0 (TID 1075)
18:59:50.005 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:59:50.005 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.007 INFO  Executor - Finished task 0.0 in stage 1236.0 (TID 1075). 1930 bytes result sent to driver
18:59:50.007 INFO  TaskSetManager - Finished task 0.0 in stage 1236.0 (TID 1075) in 4 ms on localhost (executor driver) (1/1)
18:59:50.007 INFO  TaskSchedulerImpl - Removed TaskSet 1236.0, whose tasks have all completed, from pool 
18:59:50.007 INFO  DAGScheduler - ResultStage 1236 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.005 s
18:59:50.008 INFO  DAGScheduler - Job 563 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:50.008 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1236: Stage finished
18:59:50.008 INFO  DAGScheduler - Job 563 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.025475 s
18:59:50.018 INFO  MemoryStore - Block broadcast_1998 stored as values in memory (estimated size 5.6 KiB, free 1909.7 MiB)
18:59:50.018 INFO  MemoryStore - Block broadcast_1998_piece0 stored as bytes in memory (estimated size 500.0 B, free 1909.7 MiB)
18:59:50.018 INFO  BlockManagerInfo - Added broadcast_1998_piece0 in memory on localhost:40133 (size: 500.0 B, free: 1918.5 MiB)
18:59:50.018 INFO  SparkContext - Created broadcast 1998 from broadcast at ReadsSparkSink.java:133
18:59:50.021 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:59:50.021 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:50.021 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:50.038 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:59:50.038 INFO  DAGScheduler - Registering RDD 5515 (mapToPair at SparkUtils.java:161) as input to shuffle 309
18:59:50.038 INFO  DAGScheduler - Got job 564 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:59:50.038 INFO  DAGScheduler - Final stage: ResultStage 1241 (runJob at SparkHadoopWriter.scala:83)
18:59:50.039 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1240)
18:59:50.039 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1240)
18:59:50.039 INFO  DAGScheduler - Submitting ShuffleMapStage 1240 (MapPartitionsRDD[5515] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:50.039 INFO  MemoryStore - Block broadcast_1999 stored as values in memory (estimated size 15.0 KiB, free 1909.7 MiB)
18:59:50.040 INFO  MemoryStore - Block broadcast_1999_piece0 stored as bytes in memory (estimated size 7.8 KiB, free 1909.7 MiB)
18:59:50.040 INFO  BlockManagerInfo - Added broadcast_1999_piece0 in memory on localhost:40133 (size: 7.8 KiB, free: 1918.5 MiB)
18:59:50.040 INFO  SparkContext - Created broadcast 1999 from broadcast at DAGScheduler.scala:1580
18:59:50.040 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:59:50.040 INFO  TaskSchedulerImpl - Adding task set 1240.0 with 1 tasks resource profile 0
18:59:50.040 INFO  TaskSetManager - Starting task 0.0 in stage 1240.0 (TID 1076) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:50.041 INFO  Executor - Running task 0.0 in stage 1240.0 (TID 1076)
18:59:50.042 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:59:50.042 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.043 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:59:50.043 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.044 INFO  Executor - Finished task 0.0 in stage 1240.0 (TID 1076). 1879 bytes result sent to driver
18:59:50.044 INFO  TaskSetManager - Finished task 0.0 in stage 1240.0 (TID 1076) in 4 ms on localhost (executor driver) (1/1)
18:59:50.044 INFO  TaskSchedulerImpl - Removed TaskSet 1240.0, whose tasks have all completed, from pool 
18:59:50.044 INFO  DAGScheduler - ShuffleMapStage 1240 (mapToPair at SparkUtils.java:161) finished in 0.005 s
18:59:50.044 INFO  DAGScheduler - looking for newly runnable stages
18:59:50.044 INFO  DAGScheduler - running: HashSet()
18:59:50.044 INFO  DAGScheduler - waiting: HashSet(ResultStage 1241)
18:59:50.044 INFO  DAGScheduler - failed: HashSet()
18:59:50.044 INFO  DAGScheduler - Submitting ResultStage 1241 (MapPartitionsRDD[5521] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:59:50.051 INFO  MemoryStore - Block broadcast_2000 stored as values in memory (estimated size 160.3 KiB, free 1909.5 MiB)
18:59:50.052 INFO  MemoryStore - Block broadcast_2000_piece0 stored as bytes in memory (estimated size 72.1 KiB, free 1909.5 MiB)
18:59:50.052 INFO  BlockManagerInfo - Added broadcast_2000_piece0 in memory on localhost:40133 (size: 72.1 KiB, free: 1918.4 MiB)
18:59:50.052 INFO  SparkContext - Created broadcast 2000 from broadcast at DAGScheduler.scala:1580
18:59:50.052 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:59:50.052 INFO  TaskSchedulerImpl - Adding task set 1241.0 with 1 tasks resource profile 0
18:59:50.052 INFO  TaskSetManager - Starting task 0.0 in stage 1241.0 (TID 1077) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:50.053 INFO  Executor - Running task 0.0 in stage 1241.0 (TID 1077)
18:59:50.056 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:59:50.056 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.058 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:59:50.058 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:50.058 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:50.068 INFO  FileOutputCommitter - Saved output of task 'attempt_202505191859505963656086977457908_5521_m_000000_0' to file:/tmp/MarkDups10108203777651944223/MarkDups.sam.parts/_temporary/0/task_202505191859505963656086977457908_5521_m_000000
18:59:50.068 INFO  SparkHadoopMapRedUtil - attempt_202505191859505963656086977457908_5521_m_000000_0: Committed. Elapsed time: 0 ms.
18:59:50.069 INFO  Executor - Finished task 0.0 in stage 1241.0 (TID 1077). 1858 bytes result sent to driver
18:59:50.069 INFO  TaskSetManager - Finished task 0.0 in stage 1241.0 (TID 1077) in 17 ms on localhost (executor driver) (1/1)
18:59:50.069 INFO  TaskSchedulerImpl - Removed TaskSet 1241.0, whose tasks have all completed, from pool 
18:59:50.069 INFO  DAGScheduler - ResultStage 1241 (runJob at SparkHadoopWriter.scala:83) finished in 0.024 s
18:59:50.069 INFO  DAGScheduler - Job 564 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:50.069 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1241: Stage finished
18:59:50.069 INFO  DAGScheduler - Job 564 finished: runJob at SparkHadoopWriter.scala:83, took 0.031188 s
18:59:50.069 INFO  SparkHadoopWriter - Start to commit write Job job_202505191859505963656086977457908_5521.
18:59:50.074 INFO  SparkHadoopWriter - Write Job job_202505191859505963656086977457908_5521 committed. Elapsed time: 4 ms.
18:59:50.080 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups10108203777651944223/MarkDups.sam
18:59:50.084 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups10108203777651944223/MarkDups.sam done
18:59:50.084 INFO  MarkDuplicatesSpark - Shutting down engine
[May 19, 2025 at 6:59:50 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
18:59:50.089 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:50.089 INFO  MarkDuplicatesSpark - org.broadinstitute.hellbender.tools.spark.transforms.markduplicates vUnavailable
18:59:50.089 INFO  MarkDuplicatesSpark - For support and documentation go to https://software.broadinstitute.org/gatk/
18:59:50.089 INFO  MarkDuplicatesSpark - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
18:59:50.089 INFO  MarkDuplicatesSpark - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
18:59:50.089 INFO  MarkDuplicatesSpark - Start Date/Time: May 19, 2025 at 6:59:50 PM UTC
18:59:50.089 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:50.089 INFO  MarkDuplicatesSpark - ------------------------------------------------------------
18:59:50.089 INFO  MarkDuplicatesSpark - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:59:50.089 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:59:50.090 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:59:50.090 INFO  MarkDuplicatesSpark - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:59:50.090 INFO  MarkDuplicatesSpark - Deflater: IntelDeflater
18:59:50.090 INFO  MarkDuplicatesSpark - Inflater: IntelInflater
18:59:50.090 INFO  MarkDuplicatesSpark - GCS max retries/reopens: 20
18:59:50.090 INFO  MarkDuplicatesSpark - Requester pays: disabled
18:59:50.090 INFO  MarkDuplicatesSpark - Initializing engine
18:59:50.090 INFO  MarkDuplicatesSpark - Done initializing engine
18:59:50.090 INFO  MarkDuplicatesSpark - Spark verbosity set to INFO (see --spark-verbosity argument)
18:59:50.092 INFO  MemoryStore - Block broadcast_2001 stored as values in memory (estimated size 306.3 KiB, free 1909.2 MiB)
18:59:50.099 INFO  MemoryStore - Block broadcast_2001_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1909.1 MiB)
18:59:50.099 INFO  BlockManagerInfo - Added broadcast_2001_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1918.4 MiB)
18:59:50.099 INFO  SparkContext - Created broadcast 2001 from newAPIHadoopFile at PathSplitSource.java:96
18:59:50.119 INFO  MemoryStore - Block broadcast_2002 stored as values in memory (estimated size 306.3 KiB, free 1908.8 MiB)
18:59:50.125 INFO  MemoryStore - Block broadcast_2002_piece0 stored as bytes in memory (estimated size 64.4 KiB, free 1908.7 MiB)
18:59:50.126 INFO  BlockManagerInfo - Added broadcast_2002_piece0 in memory on localhost:40133 (size: 64.4 KiB, free: 1918.3 MiB)
18:59:50.126 INFO  SparkContext - Created broadcast 2002 from newAPIHadoopFile at PathSplitSource.java:96
18:59:50.158 INFO  SparkContext - Starting job: collect at SparkUtils.java:205
18:59:50.159 INFO  FileInputFormat - Total input files to process : 1
18:59:50.159 INFO  DAGScheduler - Registering RDD 5535 (mapToPair at SparkUtils.java:161) as input to shuffle 310
18:59:50.159 INFO  DAGScheduler - Got job 565 (collect at SparkUtils.java:205) with 1 output partitions
18:59:50.159 INFO  DAGScheduler - Final stage: ResultStage 1243 (collect at SparkUtils.java:205)
18:59:50.159 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1242)
18:59:50.159 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1242)
18:59:50.159 INFO  DAGScheduler - Submitting ShuffleMapStage 1242 (MapPartitionsRDD[5535] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:50.176 INFO  MemoryStore - Block broadcast_2003 stored as values in memory (estimated size 481.4 KiB, free 1908.3 MiB)
18:59:50.178 INFO  MemoryStore - Block broadcast_2003_piece0 stored as bytes in memory (estimated size 207.4 KiB, free 1908.1 MiB)
18:59:50.179 INFO  BlockManagerInfo - Added broadcast_2003_piece0 in memory on localhost:40133 (size: 207.4 KiB, free: 1918.1 MiB)
18:59:50.179 INFO  SparkContext - Created broadcast 2003 from broadcast at DAGScheduler.scala:1580
18:59:50.179 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:59:50.179 INFO  TaskSchedulerImpl - Adding task set 1242.0 with 1 tasks resource profile 0
18:59:50.179 INFO  TaskSetManager - Starting task 0.0 in stage 1242.0 (TID 1078) (localhost, executor driver, partition 0, PROCESS_LOCAL, 9757 bytes) 
18:59:50.180 INFO  Executor - Running task 0.0 in stage 1242.0 (TID 1078)
18:59:50.210 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/walkers/MarkDuplicatesGATK/inputSingleLibrarySolexa16404.bam:0+5416
18:59:50.215 INFO  Executor - Finished task 0.0 in stage 1242.0 (TID 1078). 1148 bytes result sent to driver
18:59:50.216 INFO  TaskSetManager - Finished task 0.0 in stage 1242.0 (TID 1078) in 37 ms on localhost (executor driver) (1/1)
18:59:50.216 INFO  TaskSchedulerImpl - Removed TaskSet 1242.0, whose tasks have all completed, from pool 
18:59:50.216 INFO  DAGScheduler - ShuffleMapStage 1242 (mapToPair at SparkUtils.java:161) finished in 0.057 s
18:59:50.216 INFO  DAGScheduler - looking for newly runnable stages
18:59:50.216 INFO  DAGScheduler - running: HashSet()
18:59:50.216 INFO  DAGScheduler - waiting: HashSet(ResultStage 1243)
18:59:50.216 INFO  DAGScheduler - failed: HashSet()
18:59:50.216 INFO  DAGScheduler - Submitting ResultStage 1243 (MapPartitionsRDD[5538] at mapPartitions at SparkUtils.java:188), which has no missing parents
18:59:50.216 INFO  MemoryStore - Block broadcast_2004 stored as values in memory (estimated size 7.4 KiB, free 1908.1 MiB)
18:59:50.217 INFO  MemoryStore - Block broadcast_2004_piece0 stored as bytes in memory (estimated size 4.1 KiB, free 1908.1 MiB)
18:59:50.217 INFO  BlockManagerInfo - Added broadcast_2004_piece0 in memory on localhost:40133 (size: 4.1 KiB, free: 1918.1 MiB)
18:59:50.217 INFO  SparkContext - Created broadcast 2004 from broadcast at DAGScheduler.scala:1580
18:59:50.217 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:59:50.217 INFO  TaskSchedulerImpl - Adding task set 1243.0 with 1 tasks resource profile 0
18:59:50.217 INFO  TaskSetManager - Starting task 0.0 in stage 1243.0 (TID 1079) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:50.218 INFO  Executor - Running task 0.0 in stage 1243.0 (TID 1079)
18:59:50.218 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:59:50.218 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.220 INFO  Executor - Finished task 0.0 in stage 1243.0 (TID 1079). 2039 bytes result sent to driver
18:59:50.220 INFO  TaskSetManager - Finished task 0.0 in stage 1243.0 (TID 1079) in 3 ms on localhost (executor driver) (1/1)
18:59:50.220 INFO  TaskSchedulerImpl - Removed TaskSet 1243.0, whose tasks have all completed, from pool 
18:59:50.220 INFO  DAGScheduler - ResultStage 1243 (collect at SparkUtils.java:205) finished in 0.004 s
18:59:50.220 INFO  DAGScheduler - Job 565 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:50.220 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1243: Stage finished
18:59:50.220 INFO  DAGScheduler - Job 565 finished: collect at SparkUtils.java:205, took 0.062106 s
18:59:50.224 INFO  MemoryStore - Block broadcast_2005 stored as values in memory (estimated size 392.0 B, free 1908.1 MiB)
18:59:50.225 INFO  MemoryStore - Block broadcast_2005_piece0 stored as bytes in memory (estimated size 33.0 B, free 1908.1 MiB)
18:59:50.225 INFO  BlockManagerInfo - Added broadcast_2005_piece0 in memory on localhost:40133 (size: 33.0 B, free: 1918.1 MiB)
18:59:50.225 INFO  SparkContext - Created broadcast 2005 from broadcast at MarkDuplicatesSparkUtils.java:126
18:59:50.225 INFO  MemoryStore - Block broadcast_2006 stored as values in memory (estimated size 144.0 B, free 1908.1 MiB)
18:59:50.225 INFO  MemoryStore - Block broadcast_2006_piece0 stored as bytes in memory (estimated size 28.0 B, free 1908.1 MiB)
18:59:50.226 INFO  BlockManagerInfo - Added broadcast_2006_piece0 in memory on localhost:40133 (size: 28.0 B, free: 1918.1 MiB)
18:59:50.226 INFO  SparkContext - Created broadcast 2006 from broadcast at MarkDuplicatesSparkUtils.java:127
18:59:50.238 INFO  SparkContext - Starting job: collectAsMap at MarkDuplicatesSparkUtils.java:542
18:59:50.239 INFO  DAGScheduler - Registering RDD 5547 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) as input to shuffle 313
18:59:50.239 INFO  DAGScheduler - Registering RDD 5551 (mapToPair at MarkDuplicatesSpark.java:217) as input to shuffle 312
18:59:50.239 INFO  DAGScheduler - Registering RDD 5555 (mapToPair at MarkDuplicatesSparkUtils.java:497) as input to shuffle 311
18:59:50.239 INFO  DAGScheduler - Got job 566 (collectAsMap at MarkDuplicatesSparkUtils.java:542) with 1 output partitions
18:59:50.239 INFO  DAGScheduler - Final stage: ResultStage 1248 (collectAsMap at MarkDuplicatesSparkUtils.java:542)
18:59:50.239 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1247)
18:59:50.239 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1247)
18:59:50.239 INFO  DAGScheduler - Submitting ShuffleMapStage 1245 (MapPartitionsRDD[5547] at flatMapToPair at MarkDuplicatesSparkUtils.java:130), which has no missing parents
18:59:50.240 INFO  MemoryStore - Block broadcast_2007 stored as values in memory (estimated size 45.2 KiB, free 1908.0 MiB)
18:59:50.240 INFO  MemoryStore - Block broadcast_2007_piece0 stored as bytes in memory (estimated size 17.1 KiB, free 1908.0 MiB)
18:59:50.241 INFO  BlockManagerInfo - Added broadcast_2007_piece0 in memory on localhost:40133 (size: 17.1 KiB, free: 1918.1 MiB)
18:59:50.241 INFO  SparkContext - Created broadcast 2007 from broadcast at DAGScheduler.scala:1580
18:59:50.241 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:59:50.241 INFO  TaskSchedulerImpl - Adding task set 1245.0 with 1 tasks resource profile 0
18:59:50.241 INFO  TaskSetManager - Starting task 0.0 in stage 1245.0 (TID 1080) (localhost, executor driver, partition 0, NODE_LOCAL, 9890 bytes) 
18:59:50.241 INFO  Executor - Running task 0.0 in stage 1245.0 (TID 1080)
18:59:50.244 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:59:50.244 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.247 INFO  Executor - Finished task 0.0 in stage 1245.0 (TID 1080). 1922 bytes result sent to driver
18:59:50.247 INFO  TaskSetManager - Finished task 0.0 in stage 1245.0 (TID 1080) in 6 ms on localhost (executor driver) (1/1)
18:59:50.247 INFO  TaskSchedulerImpl - Removed TaskSet 1245.0, whose tasks have all completed, from pool 
18:59:50.247 INFO  DAGScheduler - ShuffleMapStage 1245 (flatMapToPair at MarkDuplicatesSparkUtils.java:130) finished in 0.008 s
18:59:50.247 INFO  DAGScheduler - looking for newly runnable stages
18:59:50.247 INFO  DAGScheduler - running: HashSet()
18:59:50.247 INFO  DAGScheduler - waiting: HashSet(ResultStage 1248, ShuffleMapStage 1246, ShuffleMapStage 1247)
18:59:50.247 INFO  DAGScheduler - failed: HashSet()
18:59:50.247 INFO  DAGScheduler - Submitting ShuffleMapStage 1246 (MapPartitionsRDD[5551] at mapToPair at MarkDuplicatesSpark.java:217), which has no missing parents
18:59:50.248 INFO  MemoryStore - Block broadcast_2008 stored as values in memory (estimated size 49.3 KiB, free 1907.9 MiB)
18:59:50.249 INFO  MemoryStore - Block broadcast_2008_piece0 stored as bytes in memory (estimated size 19.3 KiB, free 1907.9 MiB)
18:59:50.249 INFO  BlockManagerInfo - Added broadcast_2008_piece0 in memory on localhost:40133 (size: 19.3 KiB, free: 1918.1 MiB)
18:59:50.249 INFO  SparkContext - Created broadcast 2008 from broadcast at DAGScheduler.scala:1580
18:59:50.249 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:59:50.249 INFO  TaskSchedulerImpl - Adding task set 1246.0 with 1 tasks resource profile 0
18:59:50.249 INFO  TaskSetManager - Starting task 0.0 in stage 1246.0 (TID 1081) (localhost, executor driver, partition 0, NODE_LOCAL, 9365 bytes) 
18:59:50.249 INFO  Executor - Running task 0.0 in stage 1246.0 (TID 1081)
18:59:50.251 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:59:50.251 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.255 INFO  Executor - Finished task 0.0 in stage 1246.0 (TID 1081). 1922 bytes result sent to driver
18:59:50.255 INFO  TaskSetManager - Finished task 0.0 in stage 1246.0 (TID 1081) in 6 ms on localhost (executor driver) (1/1)
18:59:50.255 INFO  TaskSchedulerImpl - Removed TaskSet 1246.0, whose tasks have all completed, from pool 
18:59:50.256 INFO  DAGScheduler - ShuffleMapStage 1246 (mapToPair at MarkDuplicatesSpark.java:217) finished in 0.009 s
18:59:50.256 INFO  DAGScheduler - looking for newly runnable stages
18:59:50.256 INFO  DAGScheduler - running: HashSet()
18:59:50.256 INFO  DAGScheduler - waiting: HashSet(ResultStage 1248, ShuffleMapStage 1247)
18:59:50.256 INFO  DAGScheduler - failed: HashSet()
18:59:50.256 INFO  DAGScheduler - Submitting ShuffleMapStage 1247 (MapPartitionsRDD[5555] at mapToPair at MarkDuplicatesSparkUtils.java:497), which has no missing parents
18:59:50.256 INFO  MemoryStore - Block broadcast_2009 stored as values in memory (estimated size 40.0 KiB, free 1907.9 MiB)
18:59:50.257 INFO  MemoryStore - Block broadcast_2009_piece0 stored as bytes in memory (estimated size 14.5 KiB, free 1907.9 MiB)
18:59:50.257 INFO  BlockManagerInfo - Added broadcast_2009_piece0 in memory on localhost:40133 (size: 14.5 KiB, free: 1918.0 MiB)
18:59:50.257 INFO  SparkContext - Created broadcast 2009 from broadcast at DAGScheduler.scala:1580
18:59:50.257 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:59:50.257 INFO  TaskSchedulerImpl - Adding task set 1247.0 with 1 tasks resource profile 0
18:59:50.257 INFO  TaskSetManager - Starting task 0.0 in stage 1247.0 (TID 1082) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:50.258 INFO  Executor - Running task 0.0 in stage 1247.0 (TID 1082)
18:59:50.259 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:59:50.259 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.261 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:59:50.261 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.262 INFO  Executor - Finished task 0.0 in stage 1247.0 (TID 1082). 1922 bytes result sent to driver
18:59:50.262 INFO  TaskSetManager - Finished task 0.0 in stage 1247.0 (TID 1082) in 5 ms on localhost (executor driver) (1/1)
18:59:50.262 INFO  TaskSchedulerImpl - Removed TaskSet 1247.0, whose tasks have all completed, from pool 
18:59:50.262 INFO  DAGScheduler - ShuffleMapStage 1247 (mapToPair at MarkDuplicatesSparkUtils.java:497) finished in 0.006 s
18:59:50.262 INFO  DAGScheduler - looking for newly runnable stages
18:59:50.262 INFO  DAGScheduler - running: HashSet()
18:59:50.262 INFO  DAGScheduler - waiting: HashSet(ResultStage 1248)
18:59:50.262 INFO  DAGScheduler - failed: HashSet()
18:59:50.262 INFO  DAGScheduler - Submitting ResultStage 1248 (MapPartitionsRDD[5557] at mapValues at MarkDuplicatesSparkUtils.java:519), which has no missing parents
18:59:50.263 INFO  MemoryStore - Block broadcast_2010 stored as values in memory (estimated size 41.2 KiB, free 1907.8 MiB)
18:59:50.263 INFO  MemoryStore - Block broadcast_2010_piece0 stored as bytes in memory (estimated size 15.3 KiB, free 1907.8 MiB)
18:59:50.263 INFO  BlockManagerInfo - Added broadcast_2010_piece0 in memory on localhost:40133 (size: 15.3 KiB, free: 1918.0 MiB)
18:59:50.263 INFO  SparkContext - Created broadcast 2010 from broadcast at DAGScheduler.scala:1580
18:59:50.264 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:59:50.264 INFO  TaskSchedulerImpl - Adding task set 1248.0 with 1 tasks resource profile 0
18:59:50.264 INFO  TaskSetManager - Starting task 0.0 in stage 1248.0 (TID 1083) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:50.264 INFO  Executor - Running task 0.0 in stage 1248.0 (TID 1083)
18:59:50.265 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:59:50.265 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.266 INFO  Executor - Finished task 0.0 in stage 1248.0 (TID 1083). 1901 bytes result sent to driver
18:59:50.267 INFO  TaskSetManager - Finished task 0.0 in stage 1248.0 (TID 1083) in 3 ms on localhost (executor driver) (1/1)
18:59:50.267 INFO  TaskSchedulerImpl - Removed TaskSet 1248.0, whose tasks have all completed, from pool 
18:59:50.267 INFO  DAGScheduler - ResultStage 1248 (collectAsMap at MarkDuplicatesSparkUtils.java:542) finished in 0.005 s
18:59:50.267 INFO  DAGScheduler - Job 566 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:50.267 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1248: Stage finished
18:59:50.267 INFO  DAGScheduler - Job 566 finished: collectAsMap at MarkDuplicatesSparkUtils.java:542, took 0.028364 s
18:59:50.278 INFO  MemoryStore - Block broadcast_2011 stored as values in memory (estimated size 93.5 KiB, free 1907.7 MiB)
18:59:50.278 INFO  MemoryStore - Block broadcast_2011_piece0 stored as bytes in memory (estimated size 5.6 KiB, free 1907.7 MiB)
18:59:50.278 INFO  BlockManagerInfo - Added broadcast_2011_piece0 in memory on localhost:40133 (size: 5.6 KiB, free: 1918.0 MiB)
18:59:50.278 INFO  SparkContext - Created broadcast 2011 from broadcast at ReadsSparkSink.java:133
18:59:50.282 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:59:50.282 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:50.282 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:50.298 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
18:59:50.298 INFO  DAGScheduler - Registering RDD 5559 (mapToPair at SparkUtils.java:161) as input to shuffle 314
18:59:50.299 INFO  DAGScheduler - Got job 567 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
18:59:50.299 INFO  DAGScheduler - Final stage: ResultStage 1253 (runJob at SparkHadoopWriter.scala:83)
18:59:50.299 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 1252)
18:59:50.299 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 1252)
18:59:50.299 INFO  DAGScheduler - Submitting ShuffleMapStage 1252 (MapPartitionsRDD[5559] at mapToPair at SparkUtils.java:161), which has no missing parents
18:59:50.299 INFO  MemoryStore - Block broadcast_2012 stored as values in memory (estimated size 39.1 KiB, free 1907.7 MiB)
18:59:50.300 INFO  MemoryStore - Block broadcast_2012_piece0 stored as bytes in memory (estimated size 14.1 KiB, free 1907.7 MiB)
18:59:50.300 INFO  BlockManagerInfo - Added broadcast_2012_piece0 in memory on localhost:40133 (size: 14.1 KiB, free: 1918.0 MiB)
18:59:50.300 INFO  SparkContext - Created broadcast 2012 from broadcast at DAGScheduler.scala:1580
18:59:50.300 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:59:50.300 INFO  TaskSchedulerImpl - Adding task set 1252.0 with 1 tasks resource profile 0
18:59:50.301 INFO  TaskSetManager - Starting task 0.0 in stage 1252.0 (TID 1084) (localhost, executor driver, partition 0, NODE_LOCAL, 9948 bytes) 
18:59:50.301 INFO  Executor - Running task 0.0 in stage 1252.0 (TID 1084)
18:59:50.302 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:59:50.302 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.303 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:59:50.304 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.304 INFO  Executor - Finished task 0.0 in stage 1252.0 (TID 1084). 1922 bytes result sent to driver
18:59:50.305 INFO  TaskSetManager - Finished task 0.0 in stage 1252.0 (TID 1084) in 5 ms on localhost (executor driver) (1/1)
18:59:50.305 INFO  TaskSchedulerImpl - Removed TaskSet 1252.0, whose tasks have all completed, from pool 
18:59:50.305 INFO  DAGScheduler - ShuffleMapStage 1252 (mapToPair at SparkUtils.java:161) finished in 0.006 s
18:59:50.305 INFO  DAGScheduler - looking for newly runnable stages
18:59:50.305 INFO  DAGScheduler - running: HashSet()
18:59:50.305 INFO  DAGScheduler - waiting: HashSet(ResultStage 1253)
18:59:50.305 INFO  DAGScheduler - failed: HashSet()
18:59:50.305 INFO  DAGScheduler - Submitting ResultStage 1253 (MapPartitionsRDD[5565] at saveAsTextFile at SamSink.java:65), which has no missing parents
18:59:50.311 INFO  MemoryStore - Block broadcast_2013 stored as values in memory (estimated size 184.3 KiB, free 1907.5 MiB)
18:59:50.312 INFO  MemoryStore - Block broadcast_2013_piece0 stored as bytes in memory (estimated size 78.3 KiB, free 1907.4 MiB)
18:59:50.312 INFO  BlockManagerInfo - Added broadcast_2013_piece0 in memory on localhost:40133 (size: 78.3 KiB, free: 1917.9 MiB)
18:59:50.312 INFO  SparkContext - Created broadcast 2013 from broadcast at DAGScheduler.scala:1580
18:59:50.312 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:59:50.312 INFO  TaskSchedulerImpl - Adding task set 1253.0 with 1 tasks resource profile 0
18:59:50.313 INFO  TaskSetManager - Starting task 0.0 in stage 1253.0 (TID 1085) (localhost, executor driver, partition 0, NODE_LOCAL, 9376 bytes) 
18:59:50.313 INFO  Executor - Running task 0.0 in stage 1253.0 (TID 1085)
18:59:50.316 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:59:50.316 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
18:59:50.317 INFO  HadoopMapRedCommitProtocol - Using output committer class org.apache.hadoop.mapred.FileOutputCommitter
18:59:50.318 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
18:59:50.318 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
18:59:50.328 INFO  FileOutputCommitter - Saved output of task 'attempt_202505191859505615783862318916153_5565_m_000000_0' to file:/tmp/MarkDups11718967440847178573/MarkDups.sam.parts/_temporary/0/task_202505191859505615783862318916153_5565_m_000000
18:59:50.328 INFO  SparkHadoopMapRedUtil - attempt_202505191859505615783862318916153_5565_m_000000_0: Committed. Elapsed time: 0 ms.
18:59:50.328 INFO  Executor - Finished task 0.0 in stage 1253.0 (TID 1085). 1858 bytes result sent to driver
18:59:50.328 INFO  TaskSetManager - Finished task 0.0 in stage 1253.0 (TID 1085) in 15 ms on localhost (executor driver) (1/1)
18:59:50.328 INFO  TaskSchedulerImpl - Removed TaskSet 1253.0, whose tasks have all completed, from pool 
18:59:50.328 INFO  DAGScheduler - ResultStage 1253 (runJob at SparkHadoopWriter.scala:83) finished in 0.023 s
18:59:50.329 INFO  DAGScheduler - Job 567 is finished. Cancelling potential speculative or zombie tasks for this job
18:59:50.329 INFO  TaskSchedulerImpl - Killing all running tasks in stage 1253: Stage finished
18:59:50.329 INFO  DAGScheduler - Job 567 finished: runJob at SparkHadoopWriter.scala:83, took 0.030486 s
18:59:50.329 INFO  SparkHadoopWriter - Start to commit write Job job_202505191859505615783862318916153_5565.
18:59:50.333 INFO  SparkHadoopWriter - Write Job job_202505191859505615783862318916153_5565 committed. Elapsed time: 3 ms.
18:59:50.340 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/MarkDups11718967440847178573/MarkDups.sam
18:59:50.343 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/MarkDups11718967440847178573/MarkDups.sam done
18:59:50.343 INFO  MarkDuplicatesSpark - Shutting down engine
[May 19, 2025 at 6:59:50 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:50 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:50 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:51 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:51 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:51 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:52 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:52 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:52 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:53 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:53 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:53 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:54 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:54 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:54 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:54 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:55 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:55 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:55 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
18:59:56.070 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:59:56.087 ERROR TaskSetManager - Task 0 in stage 1473.0 failed 1 times; aborting job
[May 19, 2025 at 6:59:56 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
18:59:56.304 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:59:56.306 ERROR TaskSetManager - Task 0 in stage 1480.0 failed 1 times; aborting job
[May 19, 2025 at 6:59:56 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:56 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:56 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:57 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:57 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:57 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:58 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:58 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:58 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:59 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:59 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:59 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 6:59:59 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:00 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:00 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:00 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:01 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:01 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:01 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:02 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:02 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:02 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:03 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:03 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:03 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:03 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:04 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:04 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:04 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:05 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:05 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:05 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:06 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:06 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:06 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:06 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:07 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:07 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:07 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:08 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:08 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:08 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:09 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:09 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:09 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:10 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:10 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:10 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:10 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:11 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:11 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:11 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:12 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:12 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:12 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:13 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:13 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:13 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:13 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:14 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:14 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:14 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:15 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:15 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:15 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:16 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:16 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:16 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:17 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:17 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:17 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:17 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:18 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:18 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:18 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:19 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:19 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:19 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:20 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:20 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:20 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752
[May 19, 2025 at 7:00:20 PM UTC] org.broadinstitute.hellbender.tools.spark.transforms.markduplicates.MarkDuplicatesSpark done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1679818752