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

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

tests

failures

ignored

32.825s

duration

100%

successful

Tests
Standard output
Standard error

Tests

Test	Duration	Result
testAnnotationsWithNoVarianceSpecified	0.574s	passed
testBothAggregateRecalMode	5.153s	passed
testBothRecalMode	2.401s	passed
testInGatkLiteDocker	0.105s	passed
testNoNegativeTrainingData	0.708s	passed
testVQSRAnnotationOrder	0.282s	passed
testVariantRecalibratorIndel	0.837s	passed
testVariantRecalibratorModelInput	1.274s	passed
testVariantRecalibratorRScriptOutput	1.611s	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.959s	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.422s	passed
testVariantRecalibratorSNPMaxAttempts[0]([Ljava.lang.String;@767b9d66)	5.259s	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.432s	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.917s	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.506s	passed
testVariantRecalibratorSNPscattered[0]([Ljava.lang.String;@5213b887)	2.982s	passed
testVariantRecalibratorSampling	1.403s	passed

Standard output

--------------------------------------------------------------------------------
[14:14:25] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[14:14:46] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorSampling/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[14:14:48] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[14:14:50] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[14:14:50] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[14:14:51] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[14:14:51] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorIndel/gatkCloneMountPoint/src/test/resources/large/VQSR/combined.phase1.chr20.raw.indels.filtered.sites.1M-10M.vcf
--------------------------------------------------------------------------------
[14:14:52] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[14:15:56] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf

Standard error

[May 27, 2025 at 2:14:30 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.08 minutes.
Runtime.totalMemory()=1048576000
14:14:30.708 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:30.708 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:30.708 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:30.708 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:30.708 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:30.709 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:30 PM GMT
14:14:30.709 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:30.709 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:30.709 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:30.709 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:30.709 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:30.709 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:30.710 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:30.710 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:30.710 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:30.710 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:30.710 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:30.710 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:30.710 INFO  VariantRecalibrator - Requester pays: disabled
14:14:30.710 INFO  VariantRecalibrator - Initializing engine
14:14:30.713 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:14:30.738 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:14:30.829 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
14:14:30.865 INFO  VariantRecalibrator - Done initializing engine
14:14:30.866 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:30.904 INFO  ProgressMeter - Starting traversal
14:14:30.905 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:31.034 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1298139.5
14:14:31.034 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
14:14:31.035 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
14:14:31.036 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
14:14:31.037 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
14:14:31.038 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
14:14:31.047 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
14:14:31.047 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
14:14:31.047 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:31.103 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:31.131 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.16919
14:14:31.159 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.14268
14:14:31.198 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.19617
14:14:31.225 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.09047
14:14:31.246 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.05235
14:14:31.261 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04028
14:14:31.277 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02103
14:14:31.293 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01461
14:14:31.308 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01136
14:14:31.325 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00583
14:14:31.345 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00291
14:14:31.354 INFO  VariantRecalibratorEngine - Convergence after 58 iterations!
14:14:31.356 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:14:31.368 INFO  VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
14:14:31.377 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:31 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
14:14:31.381 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:14:31.414 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:31.414 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:31.414 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:31.414 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:31.414 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:31.414 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:31 PM GMT
14:14:31.414 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:31.415 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:31.415 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:31.415 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:31.415 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:31.415 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:31.415 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:31.415 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:31.415 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:31.416 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:31.416 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:31.416 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:31.416 INFO  VariantRecalibrator - Requester pays: disabled
14:14:31.416 INFO  VariantRecalibrator - Initializing engine
14:14:31.418 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:14:31.422 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
14:14:31.424 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
14:14:31.427 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:14:31.433 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:14:31.434 INFO  VariantRecalibrator - Done initializing engine
14:14:31.436 WARN  VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
14:14:31.436 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:14:31.436 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:31.436 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:14:31.439 INFO  ProgressMeter - Starting traversal
14:14:31.440 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:32.621 INFO  ProgressMeter -           20:9944766              0.0                131821        6697087.2
14:14:32.621 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
14:14:32.626 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:14:32.631 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:14:32.635 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:14:32.661 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:14:32.664 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:14:32.665 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:32.952 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:33.060 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
14:14:33.168 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
14:14:33.277 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
14:14:33.386 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
14:14:33.476 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
14:14:33.564 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
14:14:33.658 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
14:14:33.748 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
14:14:33.839 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
14:14:33.929 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
14:14:34.002 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
14:14:34.009 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:14:34.082 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
14:14:34.082 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:34.084 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:34.084 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:14:34.086 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:14:34.277 INFO  TrancheManager - Finding 4 tranches for 131821 variants
14:14:34.309 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:14:34.313 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:14:34.314 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]
14:14:34.314 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:14:34.318 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
14:14:34.319 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]
14:14:34.319 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:14:34.324 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
14:14:34.325 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]
14:14:34.325 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:14:34.331 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
14:14:34.331 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]
14:14:34.332 INFO  VariantRecalibrator - Writing out recalibration table...
14:14:34.747 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:34 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1048576000
14:14:34.813 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:14:34.844 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:34.845 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:34.845 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:34.845 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:34.845 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:34.845 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:34 PM GMT
14:14:34.845 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:34.845 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:34.845 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:34.846 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:34.846 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:34.846 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:34.846 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:34.846 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:34.846 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:34.846 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:34.846 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:34.846 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:34.846 INFO  VariantRecalibrator - Requester pays: disabled
14:14:34.846 INFO  VariantRecalibrator - Initializing engine
14:14:34.848 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:14:34.851 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
14:14:34.853 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
14:14:34.858 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:14:34.861 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:14:34.862 INFO  VariantRecalibrator - Done initializing engine
14:14:34.862 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:14:34.863 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:34.863 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:14:34.865 INFO  ProgressMeter - Starting traversal
14:14:34.865 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:35.799 INFO  ProgressMeter -           20:9944766              0.0                131821        8468158.5
14:14:35.799 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
14:14:35.802 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:14:35.805 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:14:35.808 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:14:35.830 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:14:35.832 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:14:35.832 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:36.075 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:36.181 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
14:14:36.289 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
14:14:36.375 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
14:14:36.462 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
14:14:36.550 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
14:14:36.638 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
14:14:36.728 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
14:14:36.817 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
14:14:36.907 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
14:14:36.997 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
14:14:37.077 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
14:14:37.084 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:14:37.156 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
14:14:37.156 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:37.158 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:37.158 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:14:37.159 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:14:37.344 INFO  TrancheManager - Finding 4 tranches for 131821 variants
14:14:37.375 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:14:37.379 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:14:37.379 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]
14:14:37.380 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:14:37.384 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
14:14:37.384 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]
14:14:37.384 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:14:37.389 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
14:14:37.389 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]
14:14:37.389 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:14:37.393 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
14:14:37.393 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]
14:14:37.394 INFO  VariantRecalibrator - Writing out recalibration table...
14:14:37.705 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:37 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:14:37.732 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:14:37.762 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:37.763 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:37.763 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:37.763 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:37.763 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:37.763 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:37 PM GMT
14:14:37.763 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:37.763 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:37.763 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:37.763 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:37.763 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:37.764 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:37.764 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:37.764 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:37.764 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:37.764 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:37.764 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:37.764 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:37.764 INFO  VariantRecalibrator - Requester pays: disabled
14:14:37.764 INFO  VariantRecalibrator - Initializing engine
14:14:37.766 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:14:37.784 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:14:37.842 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
14:14:37.859 INFO  VariantRecalibrator - Done initializing engine
14:14:37.860 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:37.873 INFO  ProgressMeter - Starting traversal
14:14:37.873 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:37.933 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        2791000.0
14:14:37.933 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
14:14:37.933 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
14:14:37.934 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
14:14:37.934 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
14:14:37.934 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
14:14:37.935 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
14:14:37.935 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
14:14:37.935 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:37.971 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:37.987 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
14:14:38.003 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
14:14:38.019 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
14:14:38.034 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
14:14:38.050 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
14:14:38.066 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
14:14:38.081 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
14:14:38.097 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
14:14:38.112 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
14:14:38.128 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
14:14:38.144 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
14:14:38.163 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
14:14:38.163 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
14:14:38.165 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:14:38.180 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
14:14:38.181 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:38.181 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:38.181 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:14:38.181 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:14:38.197 INFO  TrancheManager - Finding 4 tranches for 2786 variants
14:14:38.199 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:14:38.199 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:14:38.199 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]
14:14:38.199 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:14:38.199 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
14:14:38.199 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]
14:14:38.199 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:14:38.200 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
14:14:38.200 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]
14:14:38.200 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:14:38.200 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
14:14:38.200 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]
14:14:38.200 INFO  VariantRecalibrator - Writing out recalibration table...
14:14:38.232 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:38 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
14:14:38.240 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 2:14:40 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
14:14:40.675 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:40.675 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:40.675 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:40.676 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:40.676 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:40.676 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:40 PM GMT
14:14:40.676 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:40.676 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:40.676 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:40.676 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:40.676 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:40.676 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:40.676 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:40.676 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:40.676 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:40.677 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:40.677 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:40.677 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:40.677 INFO  VariantRecalibrator - Requester pays: disabled
14:14:40.677 INFO  VariantRecalibrator - Initializing engine
14:14:40.678 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:14:40.680 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
14:14:40.682 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
14:14:40.684 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:14:40.686 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/g94982_20_1m_10m_python_2dcnn.indels.vcf.gz
14:14:40.704 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:14:40.705 INFO  VariantRecalibrator - Done initializing engine
14:14:40.706 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:14:40.706 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:40.706 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:14:40.709 INFO  ProgressMeter - Starting traversal
14:14:40.710 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:41.681 INFO  ProgressMeter -           20:9938789              0.0                134919        8336910.4
14:14:41.682 INFO  ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
14:14:41.684 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:14:41.687 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:14:41.690 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:14:41.710 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:14:41.712 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:14:41.712 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:41.907 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:41.989 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.13181
14:14:42.071 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.46782
14:14:42.156 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 9.04961
14:14:42.242 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.04477
14:14:42.328 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01711
14:14:42.419 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.02053
14:14:42.487 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.01194
14:14:42.556 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01038
14:14:42.624 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.06192
14:14:42.694 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01281
14:14:42.765 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00457
14:14:42.793 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
14:14:42.798 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
14:14:42.914 INFO  VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
14:14:42.914 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:42.916 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:42.918 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.05287
14:14:42.919 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.02030
14:14:42.920 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.00986
14:14:42.921 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.00749
14:14:42.923 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.00850
14:14:42.924 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01430
14:14:42.925 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02541
14:14:42.926 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.02173
14:14:42.928 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01024
14:14:42.929 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00479
14:14:42.930 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00245
14:14:42.931 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
14:14:42.932 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
14:14:43.130 INFO  TrancheManager - Finding 4 tranches for 134603 variants
14:14:43.169 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:14:43.174 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:14:43.174 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]
14:14:43.174 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:14:43.179 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001 
14:14:43.179 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]
14:14:43.179 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:14:43.183 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010 
14:14:43.184 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]
14:14:43.184 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:14:43.188 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100 
14:14:43.188 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]
14:14:43.188 INFO  VariantRecalibrator - Writing out recalibration table...
14:14:43.498 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:43 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:14:43.500 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:14:43.519 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:43.519 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:43.519 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:43.519 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:43.519 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:43.519 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:43 PM GMT
14:14:43.519 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:43.519 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:43.520 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:43.520 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:43.520 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:43.520 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:43.520 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:43.520 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:43.520 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:43.520 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:43.520 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:43.520 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:43.520 INFO  VariantRecalibrator - Requester pays: disabled
14:14:43.520 INFO  VariantRecalibrator - Initializing engine
14:14:43.522 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:14:43.524 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
14:14:43.526 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
14:14:43.528 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:14:43.531 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:14:43.532 INFO  VariantRecalibrator - Done initializing engine
14:14:43.532 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:14:43.532 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:43.532 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:14:43.534 INFO  ProgressMeter - Starting traversal
14:14:43.534 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:44.474 INFO  ProgressMeter -           20:9944766              0.0                131821        8414106.4
14:14:44.474 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
14:14:44.476 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:14:44.479 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:14:44.482 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:14:44.506 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:14:44.507 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:14:44.507 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:44.752 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:44.858 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
14:14:44.967 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
14:14:45.078 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
14:14:45.185 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
14:14:45.273 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
14:14:45.360 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
14:14:45.450 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
14:14:45.539 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
14:14:45.629 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
14:14:45.718 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
14:14:45.790 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
14:14:45.797 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:14:45.865 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
14:14:45.865 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:45.866 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:45.867 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:14:45.868 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:14:46.056 INFO  TrancheManager - Finding 12 tranches for 131821 variants
14:14:46.095 INFO  TrancheManager -   VQSLODTranche threshold 10.00 => selection metric threshold 0.900
14:14:46.107 INFO  TrancheManager -   Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262 
14:14:46.107 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
14:14:46.107 INFO  TrancheManager -   VQSLODTranche threshold 8.00 => selection metric threshold 0.920
14:14:46.112 INFO  TrancheManager -   Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114 
14:14:46.112 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
14:14:46.112 INFO  TrancheManager -   VQSLODTranche threshold 6.00 => selection metric threshold 0.940
14:14:46.117 INFO  TrancheManager -   Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052 
14:14:46.117 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
14:14:46.117 INFO  TrancheManager -   VQSLODTranche threshold 4.00 => selection metric threshold 0.960
14:14:46.121 INFO  TrancheManager -   Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023 
14:14:46.121 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
14:14:46.121 INFO  TrancheManager -   VQSLODTranche threshold 2.00 => selection metric threshold 0.980
14:14:46.126 INFO  TrancheManager -   Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009 
14:14:46.126 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
14:14:46.126 INFO  TrancheManager -   VQSLODTranche threshold 0.00 => selection metric threshold 1.000
14:14:46.131 INFO  TrancheManager -   Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004 
14:14:46.131 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
14:14:46.131 INFO  TrancheManager -   VQSLODTranche threshold -2.00 => selection metric threshold 1.020
14:14:46.135 INFO  TrancheManager -   Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001 
14:14:46.135 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
14:14:46.135 INFO  TrancheManager -   VQSLODTranche threshold -4.00 => selection metric threshold 1.040
14:14:46.140 INFO  TrancheManager -   Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001 
14:14:46.140 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
14:14:46.140 INFO  TrancheManager -   VQSLODTranche threshold -6.00 => selection metric threshold 1.060
14:14:46.144 INFO  TrancheManager -   Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001 
14:14:46.145 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
14:14:46.145 INFO  TrancheManager -   VQSLODTranche threshold -8.00 => selection metric threshold 1.080
14:14:46.149 INFO  TrancheManager -   Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000 
14:14:46.149 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
14:14:46.149 INFO  TrancheManager -   VQSLODTranche threshold -10.00 => selection metric threshold 1.100
14:14:46.153 INFO  TrancheManager -   Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000 
14:14:46.154 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
14:14:46.154 INFO  TrancheManager -   VQSLODTranche threshold -12.00 => selection metric threshold 1.120
14:14:46.158 INFO  TrancheManager -   Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000 
14:14:46.158 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
14:14:46.158 INFO  VariantRecalibrator - Writing out recalibration table...
14:14:46.453 INFO  VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
14:14:46.460 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:46 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:14:46.483 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 2:14:47 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
14:14:47.906 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:47.906 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:47.907 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:47.907 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:47.907 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:47.907 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:47 PM GMT
14:14:47.907 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:47.907 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:47.907 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:47.907 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:47.907 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:47.907 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:47.907 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:47.907 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:47.907 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:47.907 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:47.907 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:47.907 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:47.907 INFO  VariantRecalibrator - Requester pays: disabled
14:14:47.907 INFO  VariantRecalibrator - Initializing engine
14:14:47.909 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:14:47.921 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:14:47.958 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
14:14:47.974 INFO  VariantRecalibrator - Done initializing engine
14:14:47.974 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:47.987 INFO  ProgressMeter - Starting traversal
14:14:47.987 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:48.051 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        2616562.5
14:14:48.051 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
14:14:48.051 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
14:14:48.051 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
14:14:48.051 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
14:14:48.052 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
14:14:48.052 INFO  VariantDataManager - AS_FS: 	 mean = 1.08	 standard deviation = 2.43
14:14:48.052 INFO  VariantDataManager - AS_MQRankSum: 	 mean = 0.00	 standard deviation = 0.01
14:14:48.053 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
14:14:48.053 INFO  VariantDataManager - Training with 2769 variants after standard deviation thresholding.
14:14:48.053 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:48.086 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:48.110 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.56007
14:14:48.133 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.67355
14:14:48.157 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 5.08559
14:14:48.182 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.01567
14:14:48.206 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.02021
14:14:48.230 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01989
14:14:48.254 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02504
14:14:48.279 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03657
14:14:48.303 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.04057
14:14:48.327 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.08648
14:14:48.351 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.01514
14:14:48.375 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00496
14:14:48.400 INFO  VariantRecalibratorEngine - Finished iteration 65. 	Current change in mixture coefficients = 0.00163
14:14:48.400 INFO  VariantRecalibratorEngine - Convergence after 65 iterations!
14:14:48.402 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:14:48.421 INFO  VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
14:14:48.421 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:48.421 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:48.421 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:14:48.421 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:14:48.434 INFO  TrancheManager - Finding 4 tranches for 2786 variants
14:14:48.435 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:14:48.435 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:14:48.435 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]
14:14:48.435 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:14:48.435 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
14:14:48.435 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]
14:14:48.436 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:14:48.436 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
14:14:48.436 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]
14:14:48.436 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:14:48.436 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
14:14:48.436 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]
14:14:48.436 INFO  VariantRecalibrator - Writing out recalibration table...
14:14:48.460 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:48 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
14:14:48.462 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 2:14:50 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 2:14:50 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 2:14:51 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 2:14:51 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 2:14:52 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 2:14:53 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
14:14:53.732 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:53.732 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:53.732 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:53.732 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:53.732 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:53.732 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:53 PM GMT
14:14:53.732 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:53.732 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:53.732 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:53.733 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:53.733 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:53.733 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:53.733 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:53.733 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:53.733 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:53.733 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:53.733 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:53.733 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:53.733 INFO  VariantRecalibrator - Requester pays: disabled
14:14:53.733 INFO  VariantRecalibrator - Initializing engine
14:14:53.734 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:14:53.736 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
14:14:53.738 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
14:14:53.740 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:14:53.743 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:14:53.743 INFO  VariantRecalibrator - Done initializing engine
14:14:53.744 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:14:53.744 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:53.744 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:14:53.745 INFO  ProgressMeter - Starting traversal
14:14:53.745 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:54.713 INFO  ProgressMeter -           20:9944766              0.0                131821        8170723.1
14:14:54.714 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
14:14:54.716 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:14:54.719 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:14:54.722 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:14:54.747 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:14:54.748 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:14:54.748 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:54.992 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:55.105 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
14:14:55.189 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
14:14:55.277 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
14:14:55.366 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
14:14:55.455 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
14:14:55.543 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
14:14:55.633 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
14:14:55.723 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
14:14:55.812 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
14:14:55.910 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
14:14:55.982 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
14:14:55.989 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:14:56.062 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
14:14:56.062 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:56.064 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:56.064 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:14:56.066 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:14:56.252 INFO  TrancheManager - Finding 12 tranches for 131821 variants
14:14:56.285 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:14:56.289 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:14:56.289 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]
14:14:56.289 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
14:14:56.293 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001 
14:14:56.294 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]
14:14:56.294 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:14:56.298 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
14:14:56.298 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]
14:14:56.298 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
14:14:56.302 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002 
14:14:56.302 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]
14:14:56.302 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
14:14:56.307 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004 
14:14:56.307 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]
14:14:56.307 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
14:14:56.312 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005 
14:14:56.312 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]
14:14:56.312 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
14:14:56.317 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006 
14:14:56.317 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]
14:14:56.317 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
14:14:56.321 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007 
14:14:56.321 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]
14:14:56.321 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:14:56.327 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
14:14:56.327 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]
14:14:56.327 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
14:14:56.331 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020 
14:14:56.331 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]
14:14:56.331 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
14:14:56.336 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030 
14:14:56.336 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]
14:14:56.336 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:14:56.340 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
14:14:56.341 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]
14:14:56.341 INFO  VariantRecalibrator - Writing out recalibration table...
14:14:56.642 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:56 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:14:56.664 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:14:56.688 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:56.689 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g5c95f6f-SNAPSHOT
14:14:56.689 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:14:56.689 INFO  VariantRecalibrator - Executing as root@9cd1444b9593 on Linux v6.11.0-1014-azure amd64
14:14:56.689 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:14:56.689 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 2:14:56 PM GMT
14:14:56.689 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:56.689 INFO  VariantRecalibrator - ------------------------------------------------------------
14:14:56.689 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:14:56.689 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:14:56.689 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:14:56.689 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:14:56.689 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:14:56.689 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:14:56.689 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:14:56.690 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:14:56.690 INFO  VariantRecalibrator - Inflater: IntelInflater
14:14:56.690 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:14:56.690 INFO  VariantRecalibrator - Requester pays: disabled
14:14:56.690 INFO  VariantRecalibrator - Initializing engine
14:14:56.691 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:14:56.702 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:14:56.737 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
14:14:56.749 INFO  VariantRecalibrator - Done initializing engine
14:14:56.749 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:14:56.759 INFO  ProgressMeter - Starting traversal
14:14:56.759 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:14:56.814 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        3044727.3
14:14:56.814 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
14:14:56.814 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
14:14:56.814 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
14:14:56.814 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
14:14:56.815 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
14:14:56.815 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
14:14:56.815 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
14:14:56.815 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:56.845 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:56.861 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
14:14:56.878 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
14:14:56.894 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
14:14:56.910 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
14:14:56.927 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
14:14:56.946 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
14:14:56.963 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
14:14:56.979 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
14:14:57.000 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
14:14:57.017 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
14:14:57.033 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
14:14:57.050 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
14:14:57.050 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
14:14:57.051 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:14:57.060 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
14:14:57.060 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:14:57.060 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:14:57.060 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:14:57.060 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:14:57.068 INFO  TrancheManager - Finding 12 tranches for 2786 variants
14:14:57.069 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:14:57.069 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:14:57.069 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]
14:14:57.069 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
14:14:57.069 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001 
14:14:57.069 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]
14:14:57.069 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:14:57.070 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
14:14:57.070 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]
14:14:57.070 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
14:14:57.070 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002 
14:14:57.070 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]
14:14:57.070 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
14:14:57.070 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004 
14:14:57.070 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]
14:14:57.070 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
14:14:57.070 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005 
14:14:57.070 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]
14:14:57.070 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
14:14:57.070 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006 
14:14:57.070 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]
14:14:57.070 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
14:14:57.070 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007 
14:14:57.071 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]
14:14:57.071 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:14:57.071 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
14:14:57.071 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]
14:14:57.071 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
14:14:57.071 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020 
14:14:57.071 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]
14:14:57.071 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
14:14:57.071 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030 
14:14:57.071 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]
14:14:57.071 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:14:57.071 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
14:14:57.071 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]
14:14:57.071 INFO  VariantRecalibrator - Writing out recalibration table...
14:14:57.084 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 2:14:57 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 2:15:57 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000