Class org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibratorIntegrationTest

all > org.broadinstitute.hellbender.tools.walkers.vqsr > VariantRecalibratorIntegrationTest
17

tests
0

failures
0

ignored
32.913s

duration
100%

successful

Tests

Test Duration Result
testAnnotationsWithNoVarianceSpecified 0.669s passed
testBothAggregateRecalMode 5.009s passed
testBothRecalMode 2.370s passed
testInGatkLiteDocker 0.103s passed
testNoNegativeTrainingData 0.711s passed
testVQSRAnnotationOrder 0.272s passed
testVariantRecalibratorIndel 0.838s passed
testVariantRecalibratorModelInput 1.297s passed
testVariantRecalibratorRScriptOutput 1.582s passed
testVariantRecalibratorSNPAlternateTranches[0]([Ljava.lang.String;@116915f1, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/SNPAlternateTranches.txt, /gatkCloneMountPoint/src/test/resources/large/VQSR/snpRecal.vcf) 2.946s passed
testVariantRecalibratorSNPAlternateTranches[1]([Ljava.lang.String;@1870b9b8, /gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/VQSR/expected.AS.alternate.tranches, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/expected.AS.recal.vcf) 0.416s passed
testVariantRecalibratorSNPMaxAttempts[0]([Ljava.lang.String;@767b9d66) 5.250s passed
testVariantRecalibratorSNP[0]([Ljava.lang.String;@61ce238e, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/SNPDefaultTranches.txt, /gatkCloneMountPoint/src/test/resources/large/VQSR/snpRecal.vcf) 3.384s passed
testVariantRecalibratorSNP[1]([Ljava.lang.String;@116915f1, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/SNPDefaultTranches.txt, /gatkCloneMountPoint/src/test/resources/large/VQSR/snpRecal.vcf) 2.952s passed
testVariantRecalibratorSNP[2]([Ljava.lang.String;@1870b9b8, /gatkCloneMountPoint/src/test/resources/org/broadinstitute/hellbender/tools/walkers/VQSR/expected.AS.tranches, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/expected.AS.recal.vcf) 0.581s passed
testVariantRecalibratorSNPscattered[0]([Ljava.lang.String;@5213b887) 3.009s passed
testVariantRecalibratorSampling 1.524s passed

Standard output

--------------------------------------------------------------------------------
[16:59:22] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[16:59:43] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorSampling/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[16:59:45] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[16:59:48] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[16:59:48] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[16:59:48] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[16:59:48] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorIndel/gatkCloneMountPoint/src/test/resources/large/VQSR/combined.phase1.chr20.raw.indels.filtered.sites.1M-10M.vcf
--------------------------------------------------------------------------------
[16:59:49] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[17:00:53] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf

Standard error

[May 27, 2025 at 4:59:27 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.08 minutes.
Runtime.totalMemory()=1048576000
16:59:27.595 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:27.595 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:27.595 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:27.596 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:27.596 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:27.596 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:27 PM GMT
16:59:27.596 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:27.596 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:27.596 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:27.596 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:27.597 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:27.597 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:27.597 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:27.597 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:27.597 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:27.597 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:27.597 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:27.597 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:27.597 INFO  VariantRecalibrator - Requester pays: disabled
16:59:27.597 INFO  VariantRecalibrator - Initializing engine
16:59:27.601 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:59:27.627 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:59:27.721 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
16:59:27.754 INFO  VariantRecalibrator - Done initializing engine
16:59:27.755 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:27.792 INFO  ProgressMeter - Starting traversal
16:59:27.793 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:27.940 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1139183.7
16:59:27.940 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:59:27.941 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
16:59:27.942 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
16:59:27.943 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
16:59:27.943 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
16:59:27.962 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:59:27.962 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:59:27.963 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:28.008 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:28.034 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.16919
16:59:28.062 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.14268
16:59:28.088 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.19617
16:59:28.115 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.09047
16:59:28.137 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.05235
16:59:28.153 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04028
16:59:28.171 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02103
16:59:28.192 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01461
16:59:28.207 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01136
16:59:28.223 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00583
16:59:28.239 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00291
16:59:28.248 INFO  VariantRecalibratorEngine - Convergence after 58 iterations!
16:59:28.251 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:59:28.262 INFO  VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
16:59:28.268 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:28 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
16:59:28.272 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:59:28.298 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:28.298 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:28.298 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:28.298 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:28.298 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:28.298 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:28 PM GMT
16:59:28.299 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:28.299 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:28.299 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:28.299 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:28.299 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:28.299 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:28.299 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:28.299 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:28.300 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:28.300 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:28.300 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:28.300 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:28.300 INFO  VariantRecalibrator - Requester pays: disabled
16:59:28.300 INFO  VariantRecalibrator - Initializing engine
16:59:28.302 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:59:28.305 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:59:28.308 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:59:28.311 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:59:28.314 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:59:28.315 INFO  VariantRecalibrator - Done initializing engine
16:59:28.317 WARN  VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
16:59:28.317 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:59:28.317 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:28.318 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:59:28.320 INFO  ProgressMeter - Starting traversal
16:59:28.321 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:29.315 INFO  ProgressMeter -           20:9944766              0.0                131821        7957002.0
16:59:29.316 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:59:29.322 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:59:29.330 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:59:29.336 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:59:29.363 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:59:29.368 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:59:29.368 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:29.611 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:29.724 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
16:59:29.831 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
16:59:29.940 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
16:59:30.056 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
16:59:30.145 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
16:59:30.233 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
16:59:30.323 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
16:59:30.413 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
16:59:30.504 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
16:59:30.595 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
16:59:30.671 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
16:59:30.678 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:59:30.749 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:59:30.749 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:30.751 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:30.751 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:59:30.753 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:59:30.949 INFO  TrancheManager - Finding 4 tranches for 131821 variants
16:59:30.982 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:59:30.987 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:59:30.987 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-240.7209 known=(59500 @ 2.2991) novel=(72321 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
16:59:30.988 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:59:30.992 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
16:59:30.993 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-3.1318 known=(59151 @ 2.3066) novel=(71923 @ 2.2295) truthSites(18665 accessible, 18646 called), name=anonymous]
16:59:30.993 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:59:30.997 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
16:59:30.998 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=2.2535 known=(57628 @ 2.3617) novel=(68589 @ 2.2769) truthSites(18665 accessible, 18478 called), name=anonymous]
16:59:30.998 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:59:31.002 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
16:59:31.002 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=7.6928 known=(45852 @ 2.4660) novel=(22477 @ 2.4146) truthSites(18665 accessible, 16798 called), name=anonymous]
16:59:31.003 INFO  VariantRecalibrator - Writing out recalibration table...
16:59:31.555 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:31 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:59:31.657 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:59:31.687 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:31.687 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:31.687 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:31.687 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:31.687 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:31.687 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:31 PM GMT
16:59:31.688 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:31.688 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:31.688 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:31.688 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:31.688 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:31.688 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:31.688 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:31.688 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:31.688 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:31.689 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:31.689 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:31.689 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:31.689 INFO  VariantRecalibrator - Requester pays: disabled
16:59:31.689 INFO  VariantRecalibrator - Initializing engine
16:59:31.690 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:59:31.693 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:59:31.695 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:59:31.701 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:59:31.705 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:59:31.705 INFO  VariantRecalibrator - Done initializing engine
16:59:31.706 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:59:31.706 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:31.706 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:59:31.708 INFO  ProgressMeter - Starting traversal
16:59:31.708 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:32.645 INFO  ProgressMeter -           20:9944766              0.0                131821        8441045.9
16:59:32.645 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:59:32.648 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:59:32.652 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:59:32.655 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:59:32.679 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:59:32.681 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:59:32.682 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:32.924 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:33.031 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
16:59:33.137 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
16:59:33.225 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
16:59:33.314 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
16:59:33.403 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
16:59:33.491 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
16:59:33.581 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
16:59:33.671 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
16:59:33.761 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
16:59:33.852 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
16:59:33.932 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
16:59:33.939 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:59:34.012 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:59:34.013 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:34.014 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:34.015 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:59:34.016 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:59:34.201 INFO  TrancheManager - Finding 4 tranches for 131821 variants
16:59:34.233 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:59:34.238 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:59:34.238 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-240.7209 known=(59500 @ 2.2991) novel=(72321 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
16:59:34.238 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:59:34.246 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
16:59:34.247 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-3.1318 known=(59151 @ 2.3066) novel=(71923 @ 2.2295) truthSites(18665 accessible, 18646 called), name=anonymous]
16:59:34.247 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:59:34.255 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
16:59:34.255 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=2.2535 known=(57628 @ 2.3617) novel=(68589 @ 2.2769) truthSites(18665 accessible, 18478 called), name=anonymous]
16:59:34.255 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:59:34.263 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
16:59:34.263 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=7.6928 known=(45852 @ 2.4660) novel=(22477 @ 2.4146) truthSites(18665 accessible, 16798 called), name=anonymous]
16:59:34.263 INFO  VariantRecalibrator - Writing out recalibration table...
16:59:34.585 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:34 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:59:34.610 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:59:34.636 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:34.636 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:34.636 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:34.636 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:34.637 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:34.637 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:34 PM GMT
16:59:34.637 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:34.637 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:34.637 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:34.637 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:34.637 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:34.637 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:34.638 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:34.638 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:34.638 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:34.638 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:34.638 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:34.638 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:34.638 INFO  VariantRecalibrator - Requester pays: disabled
16:59:34.638 INFO  VariantRecalibrator - Initializing engine
16:59:34.640 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:59:34.660 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:59:34.727 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
16:59:34.754 INFO  VariantRecalibrator - Done initializing engine
16:59:34.754 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:34.776 INFO  ProgressMeter - Starting traversal
16:59:34.776 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:34.876 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1691515.2
16:59:34.876 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:59:34.876 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
16:59:34.876 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
16:59:34.876 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
16:59:34.876 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
16:59:34.877 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:59:34.877 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:59:34.877 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:34.924 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:34.951 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
16:59:34.975 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
16:59:34.991 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
16:59:35.007 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
16:59:35.022 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
16:59:35.038 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
16:59:35.053 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
16:59:35.069 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
16:59:35.085 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
16:59:35.101 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
16:59:35.116 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
16:59:35.132 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
16:59:35.132 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
16:59:35.134 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:59:35.144 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
16:59:35.144 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:35.144 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:35.144 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:59:35.144 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:59:35.155 INFO  TrancheManager - Finding 4 tranches for 2786 variants
16:59:35.156 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:59:35.156 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:59:35.156 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-39326.4087 known=(0 @ 0.0000) novel=(2786 @ 3.2340) truthSites(2786 accessible, 2786 called), name=anonymous]
16:59:35.156 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:59:35.157 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
16:59:35.157 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-12.9282 known=(0 @ 0.0000) novel=(2783 @ 3.2295) truthSites(2786 accessible, 2783 called), name=anonymous]
16:59:35.157 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:59:35.157 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
16:59:35.157 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=626.3145 known=(0 @ 0.0000) novel=(2758 @ 3.2562) truthSites(2786 accessible, 2758 called), name=anonymous]
16:59:35.157 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:59:35.158 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
16:59:35.158 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=935.3268 known=(0 @ 0.0000) novel=(2507 @ 3.2134) truthSites(2786 accessible, 2507 called), name=anonymous]
16:59:35.158 INFO  VariantRecalibrator - Writing out recalibration table...
16:59:35.187 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:35 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
16:59:35.192 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 4:59:37 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
16:59:37.636 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:37.637 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:37.637 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:37.637 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:37.637 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:37.637 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:37 PM GMT
16:59:37.637 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:37.637 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:37.637 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:37.637 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:37.637 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:37.638 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:37.638 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:37.638 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:37.638 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:37.638 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:37.638 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:37.638 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:37.638 INFO  VariantRecalibrator - Requester pays: disabled
16:59:37.638 INFO  VariantRecalibrator - Initializing engine
16:59:37.639 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:59:37.642 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:59:37.644 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:59:37.646 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:59:37.649 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/g94982_20_1m_10m_python_2dcnn.indels.vcf.gz
16:59:37.667 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:59:37.669 INFO  VariantRecalibrator - Done initializing engine
16:59:37.669 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:59:37.669 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:37.669 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:59:37.673 INFO  ProgressMeter - Starting traversal
16:59:37.673 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:38.662 INFO  ProgressMeter -           20:9938789              0.0                134919        8185176.9
16:59:38.662 INFO  ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
16:59:38.664 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:59:38.668 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:59:38.670 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:59:38.694 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:59:38.695 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:59:38.695 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:38.889 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:38.971 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.13181
16:59:39.054 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.46782
16:59:39.139 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 9.04961
16:59:39.226 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.04477
16:59:39.313 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01711
16:59:39.396 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.02053
16:59:39.464 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.01194
16:59:39.533 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01038
16:59:39.601 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.06192
16:59:39.671 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01281
16:59:39.742 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00457
16:59:39.770 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
16:59:39.776 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
16:59:39.884 INFO  VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
16:59:39.884 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:39.886 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:39.887 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.05287
16:59:39.889 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.02030
16:59:39.890 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.00986
16:59:39.891 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.00749
16:59:39.892 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.00850
16:59:39.894 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01430
16:59:39.895 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02541
16:59:39.896 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.02173
16:59:39.897 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01024
16:59:39.899 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00479
16:59:39.900 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00245
16:59:39.900 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
16:59:39.902 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
16:59:40.083 INFO  TrancheManager - Finding 4 tranches for 134603 variants
16:59:40.116 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:59:40.120 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:59:40.120 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-246.6082 known=(61809 @ 2.2991) novel=(72794 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
16:59:40.120 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:59:40.125 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001 
16:59:40.125 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-4.2626 known=(61478 @ 2.3089) novel=(72476 @ 2.2282) truthSites(18665 accessible, 18646 called), name=anonymous]
16:59:40.125 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:59:40.130 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010 
16:59:40.130 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=0.6000 known=(59416 @ 2.3515) novel=(67263 @ 2.2813) truthSites(18665 accessible, 18478 called), name=anonymous]
16:59:40.130 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:59:40.134 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100 
16:59:40.135 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=4.4668 known=(48943 @ 2.4389) novel=(33028 @ 2.3795) truthSites(18665 accessible, 16798 called), name=anonymous]
16:59:40.135 INFO  VariantRecalibrator - Writing out recalibration table...
16:59:40.442 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:40 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:59:40.444 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:59:40.465 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:40.465 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:40.465 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:40.465 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:40.465 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:40.465 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:40 PM GMT
16:59:40.465 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:40.465 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:40.466 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:40.466 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:40.466 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:40.466 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:40.466 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:40.466 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:40.466 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:40.466 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:40.466 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:40.466 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:40.466 INFO  VariantRecalibrator - Requester pays: disabled
16:59:40.466 INFO  VariantRecalibrator - Initializing engine
16:59:40.467 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:59:40.470 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:59:40.471 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:59:40.473 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:59:40.475 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:59:40.477 INFO  VariantRecalibrator - Done initializing engine
16:59:40.477 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:59:40.477 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:40.477 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:59:40.478 INFO  ProgressMeter - Starting traversal
16:59:40.478 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:41.427 INFO  ProgressMeter -           20:9944766              0.0                131821        8334309.8
16:59:41.427 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:59:41.429 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:59:41.433 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:59:41.437 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:59:41.459 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:59:41.460 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:59:41.460 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:41.700 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:41.806 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
16:59:41.914 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
16:59:42.024 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
16:59:42.133 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
16:59:42.222 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
16:59:42.310 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
16:59:42.399 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
16:59:42.489 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
16:59:42.578 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
16:59:42.668 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
16:59:42.740 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
16:59:42.747 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:59:42.815 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:59:42.815 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:42.817 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:42.818 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:59:42.820 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:59:43.015 INFO  TrancheManager - Finding 12 tranches for 131821 variants
16:59:43.056 INFO  TrancheManager -   VQSLODTranche threshold 10.00 => selection metric threshold 0.900
16:59:43.068 INFO  TrancheManager -   Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262 
16:59:43.068 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
16:59:43.069 INFO  TrancheManager -   VQSLODTranche threshold 8.00 => selection metric threshold 0.920
16:59:43.073 INFO  TrancheManager -   Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114 
16:59:43.074 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
16:59:43.074 INFO  TrancheManager -   VQSLODTranche threshold 6.00 => selection metric threshold 0.940
16:59:43.078 INFO  TrancheManager -   Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052 
16:59:43.078 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
16:59:43.078 INFO  TrancheManager -   VQSLODTranche threshold 4.00 => selection metric threshold 0.960
16:59:43.083 INFO  TrancheManager -   Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023 
16:59:43.083 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
16:59:43.083 INFO  TrancheManager -   VQSLODTranche threshold 2.00 => selection metric threshold 0.980
16:59:43.087 INFO  TrancheManager -   Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009 
16:59:43.087 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
16:59:43.087 INFO  TrancheManager -   VQSLODTranche threshold 0.00 => selection metric threshold 1.000
16:59:43.094 INFO  TrancheManager -   Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004 
16:59:43.094 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
16:59:43.094 INFO  TrancheManager -   VQSLODTranche threshold -2.00 => selection metric threshold 1.020
16:59:43.099 INFO  TrancheManager -   Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001 
16:59:43.099 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
16:59:43.099 INFO  TrancheManager -   VQSLODTranche threshold -4.00 => selection metric threshold 1.040
16:59:43.103 INFO  TrancheManager -   Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001 
16:59:43.103 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
16:59:43.103 INFO  TrancheManager -   VQSLODTranche threshold -6.00 => selection metric threshold 1.060
16:59:43.107 INFO  TrancheManager -   Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001 
16:59:43.108 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
16:59:43.108 INFO  TrancheManager -   VQSLODTranche threshold -8.00 => selection metric threshold 1.080
16:59:43.112 INFO  TrancheManager -   Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000 
16:59:43.112 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
16:59:43.112 INFO  TrancheManager -   VQSLODTranche threshold -10.00 => selection metric threshold 1.100
16:59:43.116 INFO  TrancheManager -   Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000 
16:59:43.116 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
16:59:43.116 INFO  TrancheManager -   VQSLODTranche threshold -12.00 => selection metric threshold 1.120
16:59:43.120 INFO  TrancheManager -   Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000 
16:59:43.120 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
16:59:43.121 INFO  VariantRecalibrator - Writing out recalibration table...
16:59:43.423 INFO  VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
16:59:43.430 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:43 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:59:43.454 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 4:59:44 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
16:59:45.005 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:45.005 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:45.005 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:45.005 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:45.005 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:45.006 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:45 PM GMT
16:59:45.006 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:45.006 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:45.006 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:45.006 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:45.006 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:45.006 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:45.006 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:45.006 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:45.006 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:45.006 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:45.006 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:45.006 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:45.006 INFO  VariantRecalibrator - Requester pays: disabled
16:59:45.006 INFO  VariantRecalibrator - Initializing engine
16:59:45.008 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:59:45.025 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:59:45.084 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
16:59:45.108 INFO  VariantRecalibrator - Done initializing engine
16:59:45.108 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:45.129 INFO  ProgressMeter - Starting traversal
16:59:45.130 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:45.237 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1565046.7
16:59:45.237 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:59:45.237 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
16:59:45.237 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
16:59:45.238 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
16:59:45.238 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
16:59:45.238 INFO  VariantDataManager - AS_FS: 	 mean = 1.08	 standard deviation = 2.43
16:59:45.238 INFO  VariantDataManager - AS_MQRankSum: 	 mean = 0.00	 standard deviation = 0.01
16:59:45.239 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
16:59:45.239 INFO  VariantDataManager - Training with 2769 variants after standard deviation thresholding.
16:59:45.240 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:45.281 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:45.304 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.56007
16:59:45.327 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.67355
16:59:45.351 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 5.08559
16:59:45.375 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.01567
16:59:45.399 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.02021
16:59:45.423 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01989
16:59:45.447 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02504
16:59:45.471 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03657
16:59:45.495 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.04057
16:59:45.519 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.08648
16:59:45.544 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.01514
16:59:45.568 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00496
16:59:45.592 INFO  VariantRecalibratorEngine - Finished iteration 65. 	Current change in mixture coefficients = 0.00163
16:59:45.592 INFO  VariantRecalibratorEngine - Convergence after 65 iterations!
16:59:45.595 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:59:45.615 INFO  VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
16:59:45.615 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:45.615 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:45.615 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:59:45.616 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:59:45.630 INFO  TrancheManager - Finding 4 tranches for 2786 variants
16:59:45.630 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:59:45.630 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:59:45.630 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-39314.8821 known=(0 @ 0.0000) novel=(2786 @ 3.2340) truthSites(2786 accessible, 2786 called), name=anonymous]
16:59:45.630 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:59:45.630 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
16:59:45.630 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-16.8308 known=(0 @ 0.0000) novel=(2783 @ 3.2295) truthSites(2786 accessible, 2783 called), name=anonymous]
16:59:45.630 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:59:45.631 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
16:59:45.631 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=1239951.3360 known=(0 @ 0.0000) novel=(2758 @ 3.2496) truthSites(2786 accessible, 2758 called), name=anonymous]
16:59:45.631 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:59:45.631 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
16:59:45.631 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=2091223.5520 known=(0 @ 0.0000) novel=(2507 @ 3.2205) truthSites(2786 accessible, 2507 called), name=anonymous]
16:59:45.631 INFO  VariantRecalibrator - Writing out recalibration table...
16:59:45.647 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:45 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
16:59:45.649 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 4:59:47 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 4:59:48 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 4:59:48 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 4:59:48 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 4:59:49 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 4:59:50 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
16:59:50.848 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:50.848 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:50.848 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:50.849 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:50.849 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:50.849 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:50 PM GMT
16:59:50.849 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:50.849 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:50.849 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:50.849 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:50.849 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:50.849 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:50.849 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:50.849 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:50.849 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:50.849 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:50.849 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:50.849 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:50.849 INFO  VariantRecalibrator - Requester pays: disabled
16:59:50.849 INFO  VariantRecalibrator - Initializing engine
16:59:50.851 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:59:50.853 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:59:50.855 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:59:50.857 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:59:50.860 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:59:50.861 INFO  VariantRecalibrator - Done initializing engine
16:59:50.861 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:59:50.861 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:50.861 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:59:50.862 INFO  ProgressMeter - Starting traversal
16:59:50.862 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:51.838 INFO  ProgressMeter -           20:9944766              0.0                131821        8103750.0
16:59:51.839 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:59:51.841 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:59:51.845 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:59:51.847 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:59:51.871 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:59:51.873 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:59:51.873 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:52.113 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:52.231 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
16:59:52.316 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
16:59:52.401 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
16:59:52.487 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
16:59:52.575 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
16:59:52.662 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
16:59:52.751 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
16:59:52.841 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
16:59:52.930 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
16:59:53.020 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
16:59:53.101 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
16:59:53.108 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:59:53.175 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:59:53.175 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:53.176 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:53.177 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:59:53.179 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:59:53.361 INFO  TrancheManager - Finding 12 tranches for 131821 variants
16:59:53.393 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:59:53.397 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:59:53.397 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-240.7209 known=(59500 @ 2.2991) novel=(72321 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
16:59:53.398 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
16:59:53.402 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001 
16:59:53.402 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.95 minVQSLod=-6.6729 known=(59316 @ 2.3020) novel=(72124 @ 2.2259) truthSites(18665 accessible, 18655 called), name=anonymous]
16:59:53.402 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:59:53.406 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
16:59:53.406 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-3.1318 known=(59151 @ 2.3066) novel=(71923 @ 2.2295) truthSites(18665 accessible, 18646 called), name=anonymous]
16:59:53.406 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
16:59:53.411 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002 
16:59:53.411 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.80 minVQSLod=-1.1986 known=(58885 @ 2.3181) novel=(71456 @ 2.2416) truthSites(18665 accessible, 18627 called), name=anonymous]
16:59:53.411 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
16:59:53.415 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004 
16:59:53.415 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.60 minVQSLod=0.1656 known=(58528 @ 2.3328) novel=(70916 @ 2.2530) truthSites(18665 accessible, 18590 called), name=anonymous]
16:59:53.415 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
16:59:53.420 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005 
16:59:53.420 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.50 minVQSLod=0.9426 known=(58256 @ 2.3427) novel=(70523 @ 2.2598) truthSites(18665 accessible, 18571 called), name=anonymous]
16:59:53.420 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
16:59:53.424 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006 
16:59:53.424 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.40 minVQSLod=1.3251 known=(58072 @ 2.3504) novel=(70172 @ 2.2640) truthSites(18665 accessible, 18553 called), name=anonymous]
16:59:53.424 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
16:59:53.429 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007 
16:59:53.429 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.30 minVQSLod=1.5909 known=(57947 @ 2.3539) novel=(69870 @ 2.2668) truthSites(18665 accessible, 18534 called), name=anonymous]
16:59:53.429 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:59:53.433 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
16:59:53.433 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=2.2535 known=(57628 @ 2.3617) novel=(68589 @ 2.2769) truthSites(18665 accessible, 18478 called), name=anonymous]
16:59:53.433 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
16:59:53.437 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020 
16:59:53.437 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=98.00 minVQSLod=3.7431 known=(56497 @ 2.3862) novel=(64651 @ 2.3078) truthSites(18665 accessible, 18291 called), name=anonymous]
16:59:53.437 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
16:59:53.442 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030 
16:59:53.442 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=97.00 minVQSLod=4.6404 known=(55330 @ 2.4003) novel=(59506 @ 2.3526) truthSites(18665 accessible, 18105 called), name=anonymous]
16:59:53.442 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:59:53.446 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
16:59:53.446 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=7.6928 known=(45852 @ 2.4660) novel=(22477 @ 2.4146) truthSites(18665 accessible, 16798 called), name=anonymous]
16:59:53.446 INFO  VariantRecalibrator - Writing out recalibration table...
16:59:53.743 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:53 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:59:53.767 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:59:53.789 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:53.789 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g113e5d7-SNAPSHOT
16:59:53.789 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:59:53.789 INFO  VariantRecalibrator - Executing as root@1c4c36ffc4f6 on Linux v6.11.0-1014-azure amd64
16:59:53.789 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:59:53.789 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:59:53 PM GMT
16:59:53.789 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:53.789 INFO  VariantRecalibrator - ------------------------------------------------------------
16:59:53.790 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:59:53.790 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:59:53.790 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:59:53.790 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:59:53.790 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:59:53.790 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:59:53.790 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:59:53.790 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:59:53.790 INFO  VariantRecalibrator - Inflater: IntelInflater
16:59:53.790 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:59:53.790 INFO  VariantRecalibrator - Requester pays: disabled
16:59:53.790 INFO  VariantRecalibrator - Initializing engine
16:59:53.792 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:59:53.810 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:59:53.844 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
16:59:53.857 INFO  VariantRecalibrator - Done initializing engine
16:59:53.857 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:59:53.867 INFO  ProgressMeter - Starting traversal
16:59:53.867 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:59:53.924 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        2937894.7
16:59:53.924 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:59:53.925 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
16:59:53.925 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
16:59:53.925 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
16:59:53.925 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
16:59:53.925 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:59:53.926 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:59:53.926 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:53.955 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:53.971 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
16:59:53.987 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
16:59:54.003 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
16:59:54.019 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
16:59:54.035 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
16:59:54.051 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
16:59:54.067 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
16:59:54.083 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
16:59:54.099 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
16:59:54.115 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
16:59:54.131 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
16:59:54.147 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
16:59:54.147 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
16:59:54.149 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:59:54.157 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
16:59:54.157 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:59:54.157 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:59:54.158 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:59:54.158 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:59:54.165 INFO  TrancheManager - Finding 12 tranches for 2786 variants
16:59:54.166 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:59:54.166 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:59:54.166 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-39326.4087 known=(0 @ 0.0000) novel=(2786 @ 3.2340) truthSites(2786 accessible, 2786 called), name=anonymous]
16:59:54.166 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
16:59:54.167 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001 
16:59:54.167 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.95 minVQSLod=-22753.7269 known=(0 @ 0.0000) novel=(2784 @ 3.2310) truthSites(2786 accessible, 2784 called), name=anonymous]
16:59:54.167 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:59:54.167 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
16:59:54.167 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-12.9282 known=(0 @ 0.0000) novel=(2783 @ 3.2295) truthSites(2786 accessible, 2783 called), name=anonymous]
16:59:54.167 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
16:59:54.167 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002 
16:59:54.167 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.80 minVQSLod=-5.7548 known=(0 @ 0.0000) novel=(2780 @ 3.2314) truthSites(2786 accessible, 2780 called), name=anonymous]
16:59:54.167 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
16:59:54.167 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004 
16:59:54.167 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.60 minVQSLod=250.6941 known=(0 @ 0.0000) novel=(2774 @ 3.2481) truthSites(2786 accessible, 2774 called), name=anonymous]
16:59:54.167 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
16:59:54.168 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005 
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.50 minVQSLod=342.2903 known=(0 @ 0.0000) novel=(2772 @ 3.2515) truthSites(2786 accessible, 2772 called), name=anonymous]
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
16:59:54.168 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006 
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.40 minVQSLod=511.3402 known=(0 @ 0.0000) novel=(2769 @ 3.2469) truthSites(2786 accessible, 2769 called), name=anonymous]
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
16:59:54.168 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007 
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.30 minVQSLod=573.6691 known=(0 @ 0.0000) novel=(2766 @ 3.2423) truthSites(2786 accessible, 2766 called), name=anonymous]
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:59:54.168 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=626.3145 known=(0 @ 0.0000) novel=(2758 @ 3.2562) truthSites(2786 accessible, 2758 called), name=anonymous]
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
16:59:54.168 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020 
16:59:54.168 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=98.00 minVQSLod=710.0883 known=(0 @ 0.0000) novel=(2730 @ 3.2523) truthSites(2786 accessible, 2730 called), name=anonymous]
16:59:54.169 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
16:59:54.169 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030 
16:59:54.169 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=97.00 minVQSLod=758.5107 known=(0 @ 0.0000) novel=(2702 @ 3.2484) truthSites(2786 accessible, 2702 called), name=anonymous]
16:59:54.169 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:59:54.169 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
16:59:54.169 INFO  TrancheManager -   TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=935.3268 known=(0 @ 0.0000) novel=(2507 @ 3.2134) truthSites(2786 accessible, 2507 called), name=anonymous]
16:59:54.169 INFO  VariantRecalibrator - Writing out recalibration table...
16:59:54.181 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:59:54 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 5:00:54 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000