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

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

tests
0

failures
0

ignored
32.828s

duration
100%

successful

Tests

Test Duration Result
testAnnotationsWithNoVarianceSpecified 0.599s passed
testBothAggregateRecalMode 5.070s passed
testBothRecalMode 2.487s passed
testInGatkLiteDocker 0.100s passed
testNoNegativeTrainingData 0.523s passed
testVQSRAnnotationOrder 0.242s passed
testVariantRecalibratorIndel 0.883s passed
testVariantRecalibratorModelInput 1.296s passed
testVariantRecalibratorRScriptOutput 1.622s 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.888s 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.426s passed
testVariantRecalibratorSNPMaxAttempts[0]([Ljava.lang.String;@767b9d66) 5.365s 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.258s passed
testVariantRecalibratorSNP[1]([Ljava.lang.String;@116915f1, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/SNPDefaultTranches.txt, /gatkCloneMountPoint/src/test/resources/large/VQSR/snpRecal.vcf) 3.002s 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.607s passed
testVariantRecalibratorSNPscattered[0]([Ljava.lang.String;@5213b887) 3.049s passed
testVariantRecalibratorSampling 1.411s passed

Standard output

--------------------------------------------------------------------------------
[14:45:15] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[14:45:35] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorSampling/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[14:45:37] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[14:45:40] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[14:45:40] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[14:45:40] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[14:45:40] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorIndel/gatkCloneMountPoint/src/test/resources/large/VQSR/combined.phase1.chr20.raw.indels.filtered.sites.1M-10M.vcf
--------------------------------------------------------------------------------
[14:45:41] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[14:46:46] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf

Standard error

[June 2, 2025 at 2:45:20 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.08 minutes.
Runtime.totalMemory()=1048576000
14:45:20.185 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:20.185 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:20.185 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:20.186 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:20.186 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:20.186 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:20 PM GMT
14:45:20.186 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:20.186 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:20.186 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:20.186 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:20.187 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:20.187 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:20.187 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:20.187 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:20.187 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:20.187 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:20.187 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:20.187 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:20.187 INFO  VariantRecalibrator - Requester pays: disabled
14:45:20.188 INFO  VariantRecalibrator - Initializing engine
14:45:20.191 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:45:20.208 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:45:20.267 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
14:45:20.287 INFO  VariantRecalibrator - Done initializing engine
14:45:20.288 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:20.313 INFO  ProgressMeter - Starting traversal
14:45:20.314 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:20.421 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1565046.7
14:45:20.421 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
14:45:20.422 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
14:45:20.423 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
14:45:20.423 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
14:45:20.424 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
14:45:20.427 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
14:45:20.428 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
14:45:20.428 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:20.457 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:20.474 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.16919
14:45:20.491 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.14268
14:45:20.509 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.19617
14:45:20.526 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.09047
14:45:20.543 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.05235
14:45:20.560 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04028
14:45:20.577 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02103
14:45:20.593 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01461
14:45:20.610 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01136
14:45:20.627 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00583
14:45:20.645 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00291
14:45:20.655 INFO  VariantRecalibratorEngine - Convergence after 58 iterations!
14:45:20.659 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:45:20.670 INFO  VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
14:45:20.677 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:20 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
14:45:20.681 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:45:20.706 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:20.706 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:20.706 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:20.706 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:20.707 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:20.707 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:20 PM GMT
14:45:20.707 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:20.707 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:20.707 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:20.707 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:20.708 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:20.708 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:20.708 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:20.708 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:20.708 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:20.708 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:20.708 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:20.708 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:20.708 INFO  VariantRecalibrator - Requester pays: disabled
14:45:20.708 INFO  VariantRecalibrator - Initializing engine
14:45:20.710 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:45:20.714 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:45:20.716 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:45:20.719 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:45:20.723 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:45:20.724 INFO  VariantRecalibrator - Done initializing engine
14:45:20.725 WARN  VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
14:45:20.726 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:45:20.726 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:20.726 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:45:20.729 INFO  ProgressMeter - Starting traversal
14:45:20.729 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:21.749 INFO  ProgressMeter -           20:9944766              0.0                131821        7754176.5
14:45:21.749 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
14:45:21.757 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:45:21.764 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:45:21.769 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:45:21.795 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:45:21.797 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:45:21.798 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:22.045 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:22.166 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
14:45:22.276 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
14:45:22.395 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
14:45:22.505 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
14:45:22.598 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
14:45:22.691 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
14:45:22.785 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
14:45:22.880 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
14:45:22.975 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
14:45:23.072 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
14:45:23.148 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
14:45:23.158 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:45:23.229 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
14:45:23.229 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:23.231 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:23.231 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:45:23.233 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:45:23.421 INFO  TrancheManager - Finding 4 tranches for 131821 variants
14:45:23.454 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:45:23.461 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:45:23.461 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:45:23.461 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:45:23.469 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
14:45:23.470 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:45:23.470 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:45:23.475 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
14:45:23.475 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:45:23.475 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:45:23.480 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
14:45:23.480 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:45:23.481 INFO  VariantRecalibrator - Writing out recalibration table...
14:45:23.857 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:23 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:45:23.940 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:45:23.970 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:23.970 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:23.970 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:23.970 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:23.970 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:23.970 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:23 PM GMT
14:45:23.970 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:23.970 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:23.971 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:23.971 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:23.971 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:23.971 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:23.971 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:23.971 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:23.971 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:23.971 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:23.971 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:23.971 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:23.971 INFO  VariantRecalibrator - Requester pays: disabled
14:45:23.972 INFO  VariantRecalibrator - Initializing engine
14:45:23.973 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:45:23.976 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:45:23.978 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:45:23.983 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:45:23.987 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:45:23.988 INFO  VariantRecalibrator - Done initializing engine
14:45:23.988 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:45:23.988 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:23.989 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:45:23.990 INFO  ProgressMeter - Starting traversal
14:45:23.990 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:24.941 INFO  ProgressMeter -           20:9944766              0.0                131821        8325536.8
14:45:24.941 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
14:45:24.944 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:45:24.948 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:45:24.953 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:45:24.980 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:45:24.981 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:45:24.982 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:25.222 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:25.332 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
14:45:25.436 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
14:45:25.529 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
14:45:25.623 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
14:45:25.715 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
14:45:25.808 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
14:45:25.902 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
14:45:25.997 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
14:45:26.092 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
14:45:26.187 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
14:45:26.271 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
14:45:26.278 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:45:26.351 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
14:45:26.351 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:26.352 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:26.353 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:45:26.354 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:45:26.538 INFO  TrancheManager - Finding 4 tranches for 131821 variants
14:45:26.571 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:45:26.576 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:45:26.576 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:45:26.576 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:45:26.581 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
14:45:26.581 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:45:26.581 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:45:26.589 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
14:45:26.590 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:45:26.590 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:45:26.604 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
14:45:26.604 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:45:26.605 INFO  VariantRecalibrator - Writing out recalibration table...
14:45:26.913 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:26 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:45:26.943 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:45:26.975 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:26.975 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:26.975 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:26.975 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:26.975 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:26.975 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:26 PM GMT
14:45:26.975 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:26.975 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:26.976 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:26.976 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:26.976 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:26.976 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:26.976 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:26.976 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:26.976 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:26.976 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:26.976 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:26.976 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:26.977 INFO  VariantRecalibrator - Requester pays: disabled
14:45:26.977 INFO  VariantRecalibrator - Initializing engine
14:45:26.979 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:45:26.997 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:45:27.060 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
14:45:27.087 INFO  VariantRecalibrator - Done initializing engine
14:45:27.088 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:27.112 INFO  ProgressMeter - Starting traversal
14:45:27.112 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:27.211 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1691515.2
14:45:27.212 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
14:45:27.212 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
14:45:27.212 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
14:45:27.212 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
14:45:27.212 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
14:45:27.213 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
14:45:27.213 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
14:45:27.213 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:27.258 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:27.287 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
14:45:27.316 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
14:45:27.336 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
14:45:27.353 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
14:45:27.371 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
14:45:27.388 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
14:45:27.404 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
14:45:27.421 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
14:45:27.437 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
14:45:27.454 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
14:45:27.470 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
14:45:27.487 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
14:45:27.487 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
14:45:27.488 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:45:27.503 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
14:45:27.503 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:27.503 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:27.503 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:45:27.503 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:45:27.516 INFO  TrancheManager - Finding 4 tranches for 2786 variants
14:45:27.518 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:45:27.518 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:45:27.518 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:45:27.518 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:45:27.519 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
14:45:27.519 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:45:27.519 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:45:27.519 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
14:45:27.519 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:45:27.519 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:45:27.519 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
14:45:27.519 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:45:27.520 INFO  VariantRecalibrator - Writing out recalibration table...
14:45:27.548 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:27 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
14:45:27.552 INFO  gatk - Initializing VQSR tests/resetting random number generator
[June 2, 2025 at 2:45:29 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
14:45:30.008 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:30.008 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:30.008 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:30.008 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:30.008 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:30.009 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:30 PM GMT
14:45:30.009 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:30.009 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:30.009 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:30.009 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:30.009 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:30.009 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:30.009 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:30.009 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:30.009 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:30.009 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:30.010 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:30.010 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:30.010 INFO  VariantRecalibrator - Requester pays: disabled
14:45:30.010 INFO  VariantRecalibrator - Initializing engine
14:45:30.011 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:45:30.013 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:45:30.015 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:45:30.017 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:45:30.020 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:45:30.043 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:45:30.044 INFO  VariantRecalibrator - Done initializing engine
14:45:30.044 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:45:30.044 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:30.045 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:45:30.048 INFO  ProgressMeter - Starting traversal
14:45:30.048 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:31.066 INFO  ProgressMeter -           20:9938789              0.0                134919        7952003.9
14:45:31.066 INFO  ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
14:45:31.068 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:45:31.072 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:45:31.075 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:45:31.099 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:45:31.100 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:45:31.101 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:31.295 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:31.379 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.13181
14:45:31.466 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.46782
14:45:31.554 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 9.04961
14:45:31.645 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.04477
14:45:31.740 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01711
14:45:31.812 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.02053
14:45:31.885 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.01194
14:45:31.957 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01038
14:45:32.030 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.06192
14:45:32.103 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01281
14:45:32.178 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00457
14:45:32.209 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
14:45:32.214 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
14:45:32.332 INFO  VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
14:45:32.332 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:32.334 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:32.336 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.05287
14:45:32.337 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.02030
14:45:32.338 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.00986
14:45:32.340 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.00749
14:45:32.341 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.00850
14:45:32.343 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01430
14:45:32.344 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02541
14:45:32.345 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.02173
14:45:32.347 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01024
14:45:32.348 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00479
14:45:32.350 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00245
14:45:32.350 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
14:45:32.352 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
14:45:32.548 INFO  TrancheManager - Finding 4 tranches for 134603 variants
14:45:32.591 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:45:32.595 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:45:32.596 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:45:32.596 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:45:32.600 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001 
14:45:32.600 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:45:32.600 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:45:32.605 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010 
14:45:32.605 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:45:32.605 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:45:32.609 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100 
14:45:32.609 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:45:32.609 INFO  VariantRecalibrator - Writing out recalibration table...
14:45:32.917 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:32 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:45:32.919 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:45:32.936 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:32.937 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:32.937 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:32.937 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:32.937 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:32.937 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:32 PM GMT
14:45:32.937 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:32.937 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:32.937 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:32.937 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:32.937 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:32.937 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:32.938 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:32.938 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:32.938 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:32.938 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:32.938 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:32.938 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:32.938 INFO  VariantRecalibrator - Requester pays: disabled
14:45:32.938 INFO  VariantRecalibrator - Initializing engine
14:45:32.939 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:45:32.942 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:45:32.943 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:45:32.945 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:45:32.947 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:45:32.948 INFO  VariantRecalibrator - Done initializing engine
14:45:32.948 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:45:32.948 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:32.948 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:45:32.949 INFO  ProgressMeter - Starting traversal
14:45:32.949 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:33.894 INFO  ProgressMeter -           20:9944766              0.0                131821        8369587.3
14:45:33.894 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
14:45:33.897 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:45:33.900 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:45:33.903 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:45:33.927 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:45:33.929 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:45:33.929 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:34.171 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:34.281 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
14:45:34.393 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
14:45:34.510 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
14:45:34.603 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
14:45:34.698 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
14:45:34.791 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
14:45:34.886 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
14:45:34.981 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
14:45:35.076 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
14:45:35.172 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
14:45:35.248 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
14:45:35.255 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:45:35.328 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
14:45:35.328 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:35.330 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:35.330 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:45:35.332 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:45:35.526 INFO  TrancheManager - Finding 12 tranches for 131821 variants
14:45:35.564 INFO  TrancheManager -   VQSLODTranche threshold 10.00 => selection metric threshold 0.900
14:45:35.576 INFO  TrancheManager -   Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262 
14:45:35.576 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
14:45:35.576 INFO  TrancheManager -   VQSLODTranche threshold 8.00 => selection metric threshold 0.920
14:45:35.583 INFO  TrancheManager -   Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114 
14:45:35.583 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
14:45:35.583 INFO  TrancheManager -   VQSLODTranche threshold 6.00 => selection metric threshold 0.940
14:45:35.588 INFO  TrancheManager -   Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052 
14:45:35.588 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
14:45:35.588 INFO  TrancheManager -   VQSLODTranche threshold 4.00 => selection metric threshold 0.960
14:45:35.593 INFO  TrancheManager -   Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023 
14:45:35.593 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
14:45:35.593 INFO  TrancheManager -   VQSLODTranche threshold 2.00 => selection metric threshold 0.980
14:45:35.598 INFO  TrancheManager -   Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009 
14:45:35.598 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
14:45:35.599 INFO  TrancheManager -   VQSLODTranche threshold 0.00 => selection metric threshold 1.000
14:45:35.604 INFO  TrancheManager -   Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004 
14:45:35.605 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
14:45:35.605 INFO  TrancheManager -   VQSLODTranche threshold -2.00 => selection metric threshold 1.020
14:45:35.609 INFO  TrancheManager -   Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001 
14:45:35.609 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
14:45:35.609 INFO  TrancheManager -   VQSLODTranche threshold -4.00 => selection metric threshold 1.040
14:45:35.613 INFO  TrancheManager -   Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001 
14:45:35.614 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
14:45:35.614 INFO  TrancheManager -   VQSLODTranche threshold -6.00 => selection metric threshold 1.060
14:45:35.618 INFO  TrancheManager -   Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001 
14:45:35.618 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
14:45:35.618 INFO  TrancheManager -   VQSLODTranche threshold -8.00 => selection metric threshold 1.080
14:45:35.623 INFO  TrancheManager -   Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000 
14:45:35.623 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
14:45:35.623 INFO  TrancheManager -   VQSLODTranche threshold -10.00 => selection metric threshold 1.100
14:45:35.627 INFO  TrancheManager -   Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000 
14:45:35.628 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
14:45:35.628 INFO  TrancheManager -   VQSLODTranche threshold -12.00 => selection metric threshold 1.120
14:45:35.633 INFO  TrancheManager -   Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000 
14:45:35.633 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
14:45:35.633 INFO  VariantRecalibrator - Writing out recalibration table...
14:45:35.938 INFO  VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
14:45:35.945 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:35 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:45:35.968 INFO  gatk - Initializing VQSR tests/resetting random number generator
[June 2, 2025 at 2:45:37 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
14:45:37.400 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:37.400 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:37.400 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:37.400 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:37.400 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:37.400 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:37 PM GMT
14:45:37.400 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:37.401 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:37.401 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:37.401 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:37.401 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:37.401 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:37.401 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:37.401 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:37.401 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:37.401 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:37.401 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:37.401 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:37.401 INFO  VariantRecalibrator - Requester pays: disabled
14:45:37.401 INFO  VariantRecalibrator - Initializing engine
14:45:37.403 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:45:37.415 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:45:37.453 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
14:45:37.469 INFO  VariantRecalibrator - Done initializing engine
14:45:37.469 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:37.482 INFO  ProgressMeter - Starting traversal
14:45:37.482 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:37.551 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        2426956.5
14:45:37.551 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
14:45:37.552 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
14:45:37.552 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
14:45:37.552 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
14:45:37.552 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
14:45:37.552 INFO  VariantDataManager - AS_FS: 	 mean = 1.08	 standard deviation = 2.43
14:45:37.552 INFO  VariantDataManager - AS_MQRankSum: 	 mean = 0.00	 standard deviation = 0.01
14:45:37.554 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
14:45:37.554 INFO  VariantDataManager - Training with 2769 variants after standard deviation thresholding.
14:45:37.554 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:37.587 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:37.612 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.56007
14:45:37.638 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.67355
14:45:37.664 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 5.08559
14:45:37.690 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.01567
14:45:37.716 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.02021
14:45:37.742 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01989
14:45:37.768 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02504
14:45:37.794 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03657
14:45:37.820 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.04057
14:45:37.846 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.08648
14:45:37.872 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.01514
14:45:37.898 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00496
14:45:37.924 INFO  VariantRecalibratorEngine - Finished iteration 65. 	Current change in mixture coefficients = 0.00163
14:45:37.924 INFO  VariantRecalibratorEngine - Convergence after 65 iterations!
14:45:37.927 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:45:37.947 INFO  VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
14:45:37.947 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:37.947 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:37.948 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:45:37.948 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:45:37.962 INFO  TrancheManager - Finding 4 tranches for 2786 variants
14:45:37.962 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:45:37.962 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:45:37.963 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:45:37.963 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:45:37.963 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
14:45:37.963 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:45:37.963 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:45:37.963 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
14:45:37.963 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:45:37.963 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:45:37.963 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
14:45:37.963 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:45:37.964 INFO  VariantRecalibrator - Writing out recalibration table...
14:45:37.978 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:37 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
14:45:37.980 INFO  gatk - Initializing VQSR tests/resetting random number generator
[June 2, 2025 at 2:45:40 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
[June 2, 2025 at 2:45:40 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[June 2, 2025 at 2:45:40 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[June 2, 2025 at 2:45:40 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[June 2, 2025 at 2:45:41 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[June 2, 2025 at 2:45:43 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1048576000
14:45:43.339 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:43.339 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:43.339 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:43.340 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:43.340 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:43.340 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:43 PM GMT
14:45:43.340 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:43.340 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:43.340 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:43.340 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:43.340 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:43.340 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:43.340 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:43.340 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:43.340 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:43.340 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:43.340 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:43.340 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:43.340 INFO  VariantRecalibrator - Requester pays: disabled
14:45:43.340 INFO  VariantRecalibrator - Initializing engine
14:45:43.341 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
14:45:43.343 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:45:43.345 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:45:43.346 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
14:45:43.348 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
14:45:43.349 INFO  VariantRecalibrator - Done initializing engine
14:45:43.350 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
14:45:43.350 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:43.350 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
14:45:43.351 INFO  ProgressMeter - Starting traversal
14:45:43.351 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:44.297 INFO  ProgressMeter -           20:9944766              0.0                131821        8369587.3
14:45:44.297 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
14:45:44.299 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
14:45:44.303 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
14:45:44.306 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
14:45:44.333 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
14:45:44.335 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
14:45:44.345 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:44.536 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:44.623 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
14:45:44.712 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
14:45:44.801 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
14:45:44.893 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
14:45:44.986 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
14:45:45.078 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
14:45:45.172 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
14:45:45.266 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
14:45:45.360 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
14:45:45.463 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
14:45:45.538 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
14:45:45.545 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:45:45.613 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
14:45:45.613 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:45.615 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:45.615 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:45:45.617 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
14:45:45.797 INFO  TrancheManager - Finding 12 tranches for 131821 variants
14:45:45.830 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:45:45.835 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:45:45.835 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:45:45.835 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
14:45:45.840 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001 
14:45:45.840 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:45:45.840 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:45:45.844 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
14:45:45.844 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:45:45.845 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
14:45:45.849 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002 
14:45:45.849 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:45:45.849 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
14:45:45.853 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004 
14:45:45.853 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:45:45.853 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
14:45:45.858 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005 
14:45:45.858 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:45:45.858 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
14:45:45.862 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006 
14:45:45.862 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:45:45.862 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
14:45:45.866 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007 
14:45:45.866 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:45:45.866 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:45:45.870 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
14:45:45.871 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:45:45.871 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
14:45:45.876 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020 
14:45:45.876 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:45:45.876 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
14:45:45.884 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030 
14:45:45.884 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:45:45.884 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:45:45.889 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
14:45:45.889 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:45:45.889 INFO  VariantRecalibrator - Writing out recalibration table...
14:45:46.185 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:46 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
14:45:46.207 INFO  gatk - Initializing VQSR tests/resetting random number generator
14:45:46.229 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:46.229 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-7-g5749ecb-SNAPSHOT
14:45:46.229 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
14:45:46.229 INFO  VariantRecalibrator - Executing as root@7f71e7f19701 on Linux v6.11.0-1014-azure amd64
14:45:46.229 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
14:45:46.229 INFO  VariantRecalibrator - Start Date/Time: June 2, 2025 at 2:45:46 PM GMT
14:45:46.229 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:46.229 INFO  VariantRecalibrator - ------------------------------------------------------------
14:45:46.229 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
14:45:46.229 INFO  VariantRecalibrator - Picard Version: 3.4.0
14:45:46.229 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
14:45:46.229 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
14:45:46.229 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
14:45:46.229 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
14:45:46.230 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
14:45:46.230 INFO  VariantRecalibrator - Deflater: IntelDeflater
14:45:46.230 INFO  VariantRecalibrator - Inflater: IntelInflater
14:45:46.230 INFO  VariantRecalibrator - GCS max retries/reopens: 20
14:45:46.230 INFO  VariantRecalibrator - Requester pays: disabled
14:45:46.230 INFO  VariantRecalibrator - Initializing engine
14:45:46.231 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:45:46.241 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
14:45:46.281 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
14:45:46.292 INFO  VariantRecalibrator - Done initializing engine
14:45:46.292 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
14:45:46.302 INFO  ProgressMeter - Starting traversal
14:45:46.302 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
14:45:46.359 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        2937894.7
14:45:46.359 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
14:45:46.359 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
14:45:46.359 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
14:45:46.359 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
14:45:46.360 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
14:45:46.360 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
14:45:46.360 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
14:45:46.360 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:46.389 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:46.407 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
14:45:46.424 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
14:45:46.441 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
14:45:46.458 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
14:45:46.475 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
14:45:46.493 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
14:45:46.510 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
14:45:46.527 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
14:45:46.545 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
14:45:46.562 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
14:45:46.580 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
14:45:46.597 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
14:45:46.597 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
14:45:46.599 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:45:46.608 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
14:45:46.608 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
14:45:46.608 INFO  VariantRecalibratorEngine - Finished iteration 0.
14:45:46.608 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
14:45:46.608 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
14:45:46.616 INFO  TrancheManager - Finding 12 tranches for 2786 variants
14:45:46.616 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
14:45:46.617 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
14:45:46.617 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:45:46.617 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
14:45:46.617 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001 
14:45:46.617 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:45:46.617 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
14:45:46.617 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
14:45:46.617 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:45:46.617 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
14:45:46.617 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002 
14:45:46.617 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:45:46.617 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
14:45:46.618 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004 
14:45:46.618 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:45:46.618 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
14:45:46.618 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005 
14:45:46.618 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:45:46.618 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
14:45:46.618 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006 
14:45:46.618 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:45:46.618 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
14:45:46.618 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007 
14:45:46.618 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:45:46.618 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
14:45:46.619 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
14:45:46.619 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:45:46.619 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
14:45:46.619 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020 
14:45:46.619 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:45:46.619 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
14:45:46.619 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030 
14:45:46.619 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:45:46.619 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
14:45:46.619 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
14:45:46.619 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:45:46.619 INFO  VariantRecalibrator - Writing out recalibration table...
14:45:46.631 INFO  VariantRecalibrator - Shutting down engine
[June 2, 2025 at 2:45:46 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[June 2, 2025 at 2:46:47 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000