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

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

tests
0

failures
0

ignored
32.668s

duration
100%

successful

Tests

Test Duration Result
testAnnotationsWithNoVarianceSpecified 0.638s passed
testBothAggregateRecalMode 4.758s passed
testBothRecalMode 2.422s passed
testInGatkLiteDocker 0.111s passed
testNoNegativeTrainingData 0.536s passed
testVQSRAnnotationOrder 0.286s passed
testVariantRecalibratorIndel 0.838s passed
testVariantRecalibratorModelInput 1.277s passed
testVariantRecalibratorRScriptOutput 1.591s passed
testVariantRecalibratorSNPAlternateTranches[0]([Ljava.lang.String;@48aaaed9, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/SNPAlternateTranches.txt, /gatkCloneMountPoint/src/test/resources/large/VQSR/snpRecal.vcf) 2.985s passed
testVariantRecalibratorSNPAlternateTranches[1]([Ljava.lang.String;@3051e476, /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.402s passed
testVariantRecalibratorSNPMaxAttempts[0]([Ljava.lang.String;@581e8969) 5.435s 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.324s passed
testVariantRecalibratorSNP[1]([Ljava.lang.String;@48aaaed9, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/SNPDefaultTranches.txt, /gatkCloneMountPoint/src/test/resources/large/VQSR/snpRecal.vcf) 3.100s passed
testVariantRecalibratorSNP[2]([Ljava.lang.String;@3051e476, /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.462s passed
testVariantRecalibratorSNPscattered[0]([Ljava.lang.String;@1f3aa970) 3.070s passed
testVariantRecalibratorSampling 1.433s passed

Standard output

--------------------------------------------------------------------------------
[16:09:56] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[16:10:17] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorSampling/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[16:10:19] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[16:10:21] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[16:10:21] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[16:10:21] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[16:10:21] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorIndel/gatkCloneMountPoint/src/test/resources/large/VQSR/combined.phase1.chr20.raw.indels.filtered.sites.1M-10M.vcf
--------------------------------------------------------------------------------
[16:10:22] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[16:11:26] 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:10:01 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.07 minutes.
Runtime.totalMemory()=991952896
16:10:01.177 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:01.177 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:01.177 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:01.178 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:01.178 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:01.178 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:01 PM GMT
16:10:01.178 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:01.178 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:01.179 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:01.179 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:01.179 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:01.179 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:01.179 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:01.179 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:01.179 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:01.179 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:01.179 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:01.180 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:01.180 INFO  VariantRecalibrator - Requester pays: disabled
16:10:01.180 INFO  VariantRecalibrator - Initializing engine
16:10:01.182 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:10:01.199 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:10:01.258 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
16:10:01.280 INFO  VariantRecalibrator - Done initializing engine
16:10:01.280 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:01.307 INFO  ProgressMeter - Starting traversal
16:10:01.308 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:01.399 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1840219.8
16:10:01.400 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:10:01.401 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
16:10:01.402 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
16:10:01.402 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
16:10:01.403 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
16:10:01.408 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:10:01.408 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:10:01.409 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:01.439 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:01.458 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.16919
16:10:01.475 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.14268
16:10:01.494 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.19617
16:10:01.511 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.09047
16:10:01.529 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.05235
16:10:01.546 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04028
16:10:01.563 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02103
16:10:01.581 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01461
16:10:01.606 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01136
16:10:01.632 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00583
16:10:01.649 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00291
16:10:01.660 INFO  VariantRecalibratorEngine - Convergence after 58 iterations!
16:10:01.663 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:10:01.673 INFO  VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
16:10:01.680 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:01 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=991952896
16:10:01.684 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:10:01.710 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:01.711 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:01.711 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:01.711 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:01.711 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:01.711 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:01 PM GMT
16:10:01.711 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:01.711 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:01.712 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:01.712 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:01.712 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:01.712 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:01.712 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:01.712 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:01.712 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:01.712 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:01.712 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:01.712 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:01.713 INFO  VariantRecalibrator - Requester pays: disabled
16:10:01.713 INFO  VariantRecalibrator - Initializing engine
16:10:01.714 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:10:01.718 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:10:01.721 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:10:01.723 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:10:01.727 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:10:01.728 INFO  VariantRecalibrator - Done initializing engine
16:10:01.729 WARN  VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
16:10:01.730 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:10:01.730 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:01.730 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:10:01.733 INFO  ProgressMeter - Starting traversal
16:10:01.733 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:02.786 INFO  ProgressMeter -           20:9944766              0.0                131821        7511168.1
16:10:02.786 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:10:02.792 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:10:02.797 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:10:02.801 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:10:02.827 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:10:02.831 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:10:02.832 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:03.075 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:03.181 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
16:10:03.289 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
16:10:03.398 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
16:10:03.512 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
16:10:03.605 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
16:10:03.693 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
16:10:03.783 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
16:10:03.872 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
16:10:03.962 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
16:10:04.051 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
16:10:04.123 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
16:10:04.133 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:10:04.204 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:10:04.204 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:04.205 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:04.206 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:10:04.208 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:10:04.386 INFO  TrancheManager - Finding 4 tranches for 131821 variants
16:10:04.417 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:10:04.422 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:10:04.422 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:10:04.422 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:10:04.427 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
16:10:04.427 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:10:04.427 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:10:04.432 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
16:10:04.432 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:10:04.433 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:10:04.441 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
16:10:04.441 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:10:04.442 INFO  VariantRecalibrator - Writing out recalibration table...
16:10:04.940 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:04 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1119879168
16:10:05.010 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:10:05.034 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:05.035 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:05.035 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:05.035 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:05.035 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:05.035 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:05 PM GMT
16:10:05.035 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:05.035 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:05.035 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:05.036 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:05.036 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:05.036 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:05.036 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:05.036 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:05.036 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:05.036 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:05.036 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:05.036 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:05.036 INFO  VariantRecalibrator - Requester pays: disabled
16:10:05.036 INFO  VariantRecalibrator - Initializing engine
16:10:05.038 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:10:05.042 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:10:05.045 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:10:05.051 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:10:05.056 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:10:05.058 INFO  VariantRecalibrator - Done initializing engine
16:10:05.058 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:10:05.058 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:05.058 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:10:05.060 INFO  ProgressMeter - Starting traversal
16:10:05.061 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:06.045 INFO  ProgressMeter -           20:9944766              0.0                131821        8037865.9
16:10:06.045 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:10:06.048 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:10:06.053 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:10:06.057 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:10:06.082 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:10:06.084 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:10:06.084 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:06.334 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:06.445 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
16:10:06.566 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
16:10:06.695 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
16:10:06.826 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
16:10:06.916 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
16:10:07.004 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
16:10:07.093 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
16:10:07.182 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
16:10:07.272 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
16:10:07.362 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
16:10:07.434 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
16:10:07.441 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:10:07.515 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:10:07.515 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:07.517 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:07.518 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:10:07.519 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:10:07.706 INFO  TrancheManager - Finding 4 tranches for 131821 variants
16:10:07.737 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:10:07.742 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:10:07.742 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:10:07.742 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:10:07.747 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
16:10:07.747 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:10:07.747 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:10:07.752 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
16:10:07.752 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:10:07.752 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:10:07.759 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
16:10:07.759 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:10:07.759 INFO  VariantRecalibrator - Writing out recalibration table...
16:10:08.088 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:08 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1119879168
16:10:08.110 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:10:08.145 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:08.146 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:08.146 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:08.146 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:08.146 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:08.146 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:08 PM GMT
16:10:08.146 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:08.146 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:08.146 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:08.147 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:08.147 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:08.147 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:08.147 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:08.147 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:08.147 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:08.147 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:08.147 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:08.147 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:08.147 INFO  VariantRecalibrator - Requester pays: disabled
16:10:08.147 INFO  VariantRecalibrator - Initializing engine
16:10:08.149 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:10:08.161 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:10:08.201 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
16:10:08.218 INFO  VariantRecalibrator - Done initializing engine
16:10:08.218 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:08.232 INFO  ProgressMeter - Starting traversal
16:10:08.232 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:08.277 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        3721333.3
16:10:08.277 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:10:08.277 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
16:10:08.278 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
16:10:08.278 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
16:10:08.278 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
16:10:08.279 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:10:08.279 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:10:08.279 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:08.309 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:08.326 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
16:10:08.344 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
16:10:08.361 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
16:10:08.378 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
16:10:08.396 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
16:10:08.413 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
16:10:08.430 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
16:10:08.447 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
16:10:08.465 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
16:10:08.482 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
16:10:08.500 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
16:10:08.517 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
16:10:08.518 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
16:10:08.520 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:10:08.530 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
16:10:08.530 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:08.530 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:08.530 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:10:08.531 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:10:08.542 INFO  TrancheManager - Finding 4 tranches for 2786 variants
16:10:08.545 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:10:08.545 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:10:08.545 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:10:08.545 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:10:08.546 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
16:10:08.546 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:10:08.546 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:10:08.546 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
16:10:08.546 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:10:08.546 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:10:08.547 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
16:10:08.547 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:10:08.547 INFO  VariantRecalibrator - Writing out recalibration table...
16:10:08.569 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:08 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1119879168
16:10:08.574 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 4:10:11 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1119879168
16:10:11.170 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:11.171 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:11.171 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:11.171 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:11.171 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:11.171 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:11 PM GMT
16:10:11.171 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:11.171 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:11.171 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:11.171 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:11.171 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:11.171 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:11.172 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:11.172 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:11.172 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:11.172 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:11.172 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:11.172 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:11.172 INFO  VariantRecalibrator - Requester pays: disabled
16:10:11.172 INFO  VariantRecalibrator - Initializing engine
16:10:11.173 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:10:11.175 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:10:11.177 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:10:11.178 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:10:11.181 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:10:11.203 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:10:11.204 INFO  VariantRecalibrator - Done initializing engine
16:10:11.205 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:10:11.205 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:11.205 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:10:11.207 INFO  ProgressMeter - Starting traversal
16:10:11.207 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:12.199 INFO  ProgressMeter -           20:9938789              0.0                134919        8160423.4
16:10:12.199 INFO  ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
16:10:12.202 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:10:12.207 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:10:12.210 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:10:12.231 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:10:12.233 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:10:12.233 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:12.421 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:12.502 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.13181
16:10:12.583 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.46782
16:10:12.667 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 9.04961
16:10:12.753 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.04477
16:10:12.838 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01711
16:10:12.923 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.02053
16:10:13.009 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.01194
16:10:13.077 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01038
16:10:13.145 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.06192
16:10:13.214 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01281
16:10:13.285 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00457
16:10:13.313 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
16:10:13.318 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
16:10:13.428 INFO  VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
16:10:13.429 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:13.431 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:13.432 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.05287
16:10:13.433 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.02030
16:10:13.435 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.00986
16:10:13.436 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.00749
16:10:13.437 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.00850
16:10:13.438 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01430
16:10:13.440 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02541
16:10:13.441 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.02173
16:10:13.442 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01024
16:10:13.443 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00479
16:10:13.445 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00245
16:10:13.445 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
16:10:13.447 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
16:10:13.644 INFO  TrancheManager - Finding 4 tranches for 134603 variants
16:10:13.683 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:10:13.688 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:10:13.688 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:10:13.688 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:10:13.693 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001 
16:10:13.693 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:10:13.693 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:10:13.698 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010 
16:10:13.698 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:10:13.698 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:10:13.702 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100 
16:10:13.702 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:10:13.702 INFO  VariantRecalibrator - Writing out recalibration table...
16:10:14.009 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:14 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1119879168
16:10:14.011 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:10:14.030 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:14.030 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:14.030 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:14.030 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:14.030 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:14.030 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:14 PM GMT
16:10:14.030 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:14.030 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:14.030 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:14.030 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:14.031 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:14.031 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:14.031 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:14.031 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:14.031 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:14.031 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:14.031 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:14.031 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:14.031 INFO  VariantRecalibrator - Requester pays: disabled
16:10:14.031 INFO  VariantRecalibrator - Initializing engine
16:10:14.032 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:10:14.034 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:10:14.036 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:10:14.038 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:10:14.041 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:10:14.042 INFO  VariantRecalibrator - Done initializing engine
16:10:14.042 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:10:14.042 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:14.042 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:10:14.044 INFO  ProgressMeter - Starting traversal
16:10:14.044 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:14.989 INFO  ProgressMeter -           20:9944766              0.0                131821        8378453.4
16:10:14.989 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:10:14.991 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:10:14.995 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:10:14.997 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:10:15.015 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:10:15.016 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:10:15.016 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:15.252 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:15.357 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
16:10:15.463 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
16:10:15.573 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
16:10:15.684 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
16:10:15.795 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
16:10:15.906 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
16:10:16.019 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
16:10:16.141 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
16:10:16.232 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
16:10:16.322 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
16:10:16.394 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
16:10:16.401 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:10:16.475 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:10:16.475 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:16.476 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:16.477 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:10:16.479 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:10:16.664 INFO  TrancheManager - Finding 12 tranches for 131821 variants
16:10:16.703 INFO  TrancheManager -   VQSLODTranche threshold 10.00 => selection metric threshold 0.900
16:10:16.714 INFO  TrancheManager -   Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262 
16:10:16.714 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
16:10:16.714 INFO  TrancheManager -   VQSLODTranche threshold 8.00 => selection metric threshold 0.920
16:10:16.719 INFO  TrancheManager -   Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114 
16:10:16.719 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
16:10:16.719 INFO  TrancheManager -   VQSLODTranche threshold 6.00 => selection metric threshold 0.940
16:10:16.723 INFO  TrancheManager -   Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052 
16:10:16.723 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
16:10:16.723 INFO  TrancheManager -   VQSLODTranche threshold 4.00 => selection metric threshold 0.960
16:10:16.728 INFO  TrancheManager -   Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023 
16:10:16.728 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
16:10:16.728 INFO  TrancheManager -   VQSLODTranche threshold 2.00 => selection metric threshold 0.980
16:10:16.732 INFO  TrancheManager -   Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009 
16:10:16.732 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
16:10:16.732 INFO  TrancheManager -   VQSLODTranche threshold 0.00 => selection metric threshold 1.000
16:10:16.737 INFO  TrancheManager -   Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004 
16:10:16.737 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
16:10:16.737 INFO  TrancheManager -   VQSLODTranche threshold -2.00 => selection metric threshold 1.020
16:10:16.741 INFO  TrancheManager -   Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001 
16:10:16.741 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
16:10:16.741 INFO  TrancheManager -   VQSLODTranche threshold -4.00 => selection metric threshold 1.040
16:10:16.745 INFO  TrancheManager -   Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001 
16:10:16.746 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
16:10:16.746 INFO  TrancheManager -   VQSLODTranche threshold -6.00 => selection metric threshold 1.060
16:10:16.750 INFO  TrancheManager -   Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001 
16:10:16.750 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
16:10:16.750 INFO  TrancheManager -   VQSLODTranche threshold -8.00 => selection metric threshold 1.080
16:10:16.754 INFO  TrancheManager -   Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000 
16:10:16.754 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
16:10:16.754 INFO  TrancheManager -   VQSLODTranche threshold -10.00 => selection metric threshold 1.100
16:10:16.759 INFO  TrancheManager -   Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000 
16:10:16.759 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
16:10:16.759 INFO  TrancheManager -   VQSLODTranche threshold -12.00 => selection metric threshold 1.120
16:10:16.763 INFO  TrancheManager -   Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000 
16:10:16.763 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
16:10:16.763 INFO  VariantRecalibrator - Writing out recalibration table...
16:10:17.054 INFO  VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
16:10:17.061 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:17 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1119879168
16:10:17.082 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 4:10:18 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1119879168
16:10:18.542 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:18.542 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:18.542 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:18.542 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:18.542 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:18.542 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:18 PM GMT
16:10:18.542 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:18.542 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:18.543 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:18.543 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:18.543 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:18.543 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:18.543 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:18.543 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:18.543 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:18.543 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:18.543 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:18.543 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:18.543 INFO  VariantRecalibrator - Requester pays: disabled
16:10:18.543 INFO  VariantRecalibrator - Initializing engine
16:10:18.545 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:10:18.557 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:10:18.602 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
16:10:18.616 INFO  VariantRecalibrator - Done initializing engine
16:10:18.617 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:18.631 INFO  ProgressMeter - Starting traversal
16:10:18.631 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:18.715 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1993571.4
16:10:18.715 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:10:18.716 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
16:10:18.716 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
16:10:18.716 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
16:10:18.716 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
16:10:18.716 INFO  VariantDataManager - AS_FS: 	 mean = 1.08	 standard deviation = 2.43
16:10:18.717 INFO  VariantDataManager - AS_MQRankSum: 	 mean = 0.00	 standard deviation = 0.01
16:10:18.718 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
16:10:18.718 INFO  VariantDataManager - Training with 2769 variants after standard deviation thresholding.
16:10:18.718 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:18.759 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:18.784 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.56007
16:10:18.809 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.67355
16:10:18.834 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 5.08559
16:10:18.861 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.01567
16:10:18.886 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.02021
16:10:18.912 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01989
16:10:18.937 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02504
16:10:18.963 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03657
16:10:18.988 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.04057
16:10:19.014 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.08648
16:10:19.039 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.01514
16:10:19.065 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00496
16:10:19.090 INFO  VariantRecalibratorEngine - Finished iteration 65. 	Current change in mixture coefficients = 0.00163
16:10:19.090 INFO  VariantRecalibratorEngine - Convergence after 65 iterations!
16:10:19.093 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:10:19.113 INFO  VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
16:10:19.113 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:19.113 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:19.113 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:10:19.114 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:10:19.127 INFO  TrancheManager - Finding 4 tranches for 2786 variants
16:10:19.128 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:10:19.128 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:10:19.128 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:10:19.128 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:10:19.128 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
16:10:19.128 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:10:19.128 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:10:19.129 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
16:10:19.129 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:10:19.129 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:10:19.129 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
16:10:19.129 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:10:19.129 INFO  VariantRecalibrator - Writing out recalibration table...
16:10:19.153 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:19 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1119879168
16:10:19.155 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 4:10:21 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1119879168
[May 27, 2025 at 4:10:21 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1119879168
[May 27, 2025 at 4:10:21 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1119879168
[May 27, 2025 at 4:10:21 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1119879168
[May 27, 2025 at 4:10:22 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1119879168
[May 27, 2025 at 4:10:24 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1119879168
16:10:24.435 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:24.435 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:24.436 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:24.436 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:24.436 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:24.436 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:24 PM GMT
16:10:24.436 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:24.436 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:24.436 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:24.436 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:24.436 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:24.436 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:24.436 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:24.436 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:24.436 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:24.436 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:24.436 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:24.436 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:24.436 INFO  VariantRecalibrator - Requester pays: disabled
16:10:24.436 INFO  VariantRecalibrator - Initializing engine
16:10:24.437 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:10:24.440 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:10:24.441 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:10:24.443 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:10:24.445 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
16:10:24.446 INFO  VariantRecalibrator - Done initializing engine
16:10:24.446 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
16:10:24.446 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:24.446 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
16:10:24.448 INFO  ProgressMeter - Starting traversal
16:10:24.448 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:25.436 INFO  ProgressMeter -           20:9944766              0.0                131821        8005323.9
16:10:25.437 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:10:25.439 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
16:10:25.443 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
16:10:25.445 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
16:10:25.469 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:10:25.470 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:10:25.470 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:25.707 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:25.812 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
16:10:25.922 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
16:10:26.008 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
16:10:26.096 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
16:10:26.184 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
16:10:26.272 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
16:10:26.361 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
16:10:26.450 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
16:10:26.539 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
16:10:26.634 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
16:10:26.706 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
16:10:26.712 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:10:26.793 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:10:26.793 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:26.795 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:26.795 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:10:26.796 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:10:26.980 INFO  TrancheManager - Finding 12 tranches for 131821 variants
16:10:27.012 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:10:27.018 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:10:27.018 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:10:27.018 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
16:10:27.022 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001 
16:10:27.022 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:10:27.022 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:10:27.027 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
16:10:27.027 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:10:27.027 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
16:10:27.031 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002 
16:10:27.031 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:10:27.031 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
16:10:27.035 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004 
16:10:27.035 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:10:27.035 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
16:10:27.040 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005 
16:10:27.040 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:10:27.040 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
16:10:27.044 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006 
16:10:27.044 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:10:27.044 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
16:10:27.048 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007 
16:10:27.048 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:10:27.049 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:10:27.055 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
16:10:27.055 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:10:27.055 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
16:10:27.059 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020 
16:10:27.059 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:10:27.059 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
16:10:27.066 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030 
16:10:27.066 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:10:27.067 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:10:27.073 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
16:10:27.073 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:10:27.073 INFO  VariantRecalibrator - Writing out recalibration table...
16:10:27.373 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:27 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1119879168
16:10:27.395 INFO  gatk - Initializing VQSR tests/resetting random number generator
16:10:27.413 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:27.413 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-gf5385f1-SNAPSHOT
16:10:27.413 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:10:27.413 INFO  VariantRecalibrator - Executing as root@1be272c3efa7 on Linux v6.11.0-1014-azure amd64
16:10:27.413 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:10:27.413 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 4:10:27 PM GMT
16:10:27.414 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:27.414 INFO  VariantRecalibrator - ------------------------------------------------------------
16:10:27.414 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:10:27.414 INFO  VariantRecalibrator - Picard Version: 3.4.0
16:10:27.414 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
16:10:27.414 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:10:27.414 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:10:27.414 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:10:27.414 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:10:27.414 INFO  VariantRecalibrator - Deflater: IntelDeflater
16:10:27.414 INFO  VariantRecalibrator - Inflater: IntelInflater
16:10:27.414 INFO  VariantRecalibrator - GCS max retries/reopens: 20
16:10:27.414 INFO  VariantRecalibrator - Requester pays: disabled
16:10:27.414 INFO  VariantRecalibrator - Initializing engine
16:10:27.416 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:10:27.427 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:10:27.462 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
16:10:27.475 INFO  VariantRecalibrator - Done initializing engine
16:10:27.475 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
16:10:27.485 INFO  ProgressMeter - Starting traversal
16:10:27.485 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
16:10:27.527 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        4084390.2
16:10:27.527 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:10:27.527 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
16:10:27.527 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
16:10:27.528 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
16:10:27.528 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
16:10:27.528 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:10:27.528 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:10:27.528 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:27.558 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:27.574 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
16:10:27.592 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
16:10:27.609 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
16:10:27.626 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
16:10:27.643 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
16:10:27.660 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
16:10:27.677 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
16:10:27.700 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
16:10:27.716 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
16:10:27.731 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
16:10:27.746 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
16:10:27.761 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
16:10:27.761 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
16:10:27.763 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:10:27.772 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
16:10:27.772 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:10:27.772 INFO  VariantRecalibratorEngine - Finished iteration 0.
16:10:27.772 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
16:10:27.772 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:10:27.780 INFO  TrancheManager - Finding 12 tranches for 2786 variants
16:10:27.780 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:10:27.781 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
16:10:27.781 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:10:27.781 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
16:10:27.781 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001 
16:10:27.781 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:10:27.781 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:10:27.781 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
16:10:27.781 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:10:27.781 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
16:10:27.781 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002 
16:10:27.781 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:10:27.781 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
16:10:27.782 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004 
16:10:27.782 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:10:27.782 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
16:10:27.782 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005 
16:10:27.782 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:10:27.782 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
16:10:27.782 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006 
16:10:27.782 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:10:27.782 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
16:10:27.782 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007 
16:10:27.782 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:10:27.782 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:10:27.782 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
16:10:27.782 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:10:27.782 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
16:10:27.782 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020 
16:10:27.782 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:10:27.782 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
16:10:27.783 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030 
16:10:27.783 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:10:27.783 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:10:27.783 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
16:10:27.783 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:10:27.783 INFO  VariantRecalibrator - Writing out recalibration table...
16:10:27.796 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 4:10:27 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1119879168
[May 27, 2025 at 4:11:28 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1119879168