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

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

tests
0

failures
0

ignored
32.392s

duration
100%

successful

Tests

Test Duration Result
testAnnotationsWithNoVarianceSpecified 0.665s passed
testBothAggregateRecalMode 4.888s passed
testBothRecalMode 2.344s passed
testInGatkLiteDocker 0.100s passed
testNoNegativeTrainingData 0.506s passed
testVQSRAnnotationOrder 0.236s passed
testVariantRecalibratorIndel 0.829s passed
testVariantRecalibratorModelInput 1.282s passed
testVariantRecalibratorRScriptOutput 1.599s 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.921s 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.397s passed
testVariantRecalibratorSNPMaxAttempts[0]([Ljava.lang.String;@767b9d66) 5.382s 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.338s passed
testVariantRecalibratorSNP[1]([Ljava.lang.String;@116915f1, /gatkCloneMountPoint/src/test/resources/large/VQSR/expected/SNPDefaultTranches.txt, /gatkCloneMountPoint/src/test/resources/large/VQSR/snpRecal.vcf) 2.931s 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.470s passed
testVariantRecalibratorSNPscattered[0]([Ljava.lang.String;@5213b887) 2.969s passed
testVariantRecalibratorSampling 1.535s passed

Standard output

--------------------------------------------------------------------------------
[15:21:32] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[15:21:53] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorSampling/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[15:21:55] Executing test VariantRecalibratorIntegrationTest:testBothRecalMode
--------------------------------------------------------------------------------
[15:21:57] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[15:21:58] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[15:21:58] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources//oneSNP.vcf
--------------------------------------------------------------------------------
[15:21:58] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorIndel/gatkCloneMountPoint/src/test/resources/large/VQSR/combined.phase1.chr20.raw.indels.filtered.sites.1M-10M.vcf
--------------------------------------------------------------------------------
[15:21:59] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorRscriptOutput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
--------------------------------------------------------------------------------
[15:23:01] Executing test VariantRecalibratorIntegrationTest:testVariantRecalibratorModelInput/gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf

Standard error

[May 27, 2025 at 3:21:37 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.07 minutes.
Runtime.totalMemory()=1048576000
15:21:37.837 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:37.837 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:21:37.837 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:21:37.837 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:21:37.837 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:21:37.838 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:21:37 PM GMT
15:21:37.838 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:37.838 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:37.838 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:21:37.838 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:21:37.838 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:21:37.838 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:21:37.839 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:21:37.839 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:21:37.839 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:21:37.839 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:21:37.839 INFO  VariantRecalibrator - Inflater: IntelInflater
15:21:37.839 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:21:37.839 INFO  VariantRecalibrator - Requester pays: disabled
15:21:37.839 INFO  VariantRecalibrator - Initializing engine
15:21:37.842 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
15:21:37.859 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
15:21:37.917 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
15:21:37.937 INFO  VariantRecalibrator - Done initializing engine
15:21:37.938 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:21:37.964 INFO  ProgressMeter - Starting traversal
15:21:37.964 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:21:38.064 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1674600.0
15:21:38.065 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
15:21:38.065 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
15:21:38.066 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
15:21:38.066 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
15:21:38.067 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
15:21:38.073 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
15:21:38.073 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
15:21:38.073 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:38.102 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:38.119 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.16919
15:21:38.135 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.14268
15:21:38.151 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.19617
15:21:38.167 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.09047
15:21:38.183 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.05235
15:21:38.200 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04028
15:21:38.217 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02103
15:21:38.233 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01461
15:21:38.249 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01136
15:21:38.265 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00583
15:21:38.281 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00291
15:21:38.290 INFO  VariantRecalibratorEngine - Convergence after 58 iterations!
15:21:38.292 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:21:38.302 INFO  VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
15:21:38.309 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:21:38 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
15:21:38.313 INFO  gatk - Initializing VQSR tests/resetting random number generator
15:21:38.339 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:38.339 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:21:38.339 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:21:38.339 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:21:38.340 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:21:38.340 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:21:38 PM GMT
15:21:38.340 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:38.340 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:38.340 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:21:38.340 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:21:38.340 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:21:38.341 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:21:38.341 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:21:38.341 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:21:38.341 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:21:38.341 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:21:38.341 INFO  VariantRecalibrator - Inflater: IntelInflater
15:21:38.341 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:21:38.341 INFO  VariantRecalibrator - Requester pays: disabled
15:21:38.341 INFO  VariantRecalibrator - Initializing engine
15:21:38.343 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
15:21:38.347 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
15:21:38.350 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
15:21:38.353 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
15:21:38.359 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
15:21:38.360 INFO  VariantRecalibrator - Done initializing engine
15:21:38.362 WARN  VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
15:21:38.362 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
15:21:38.362 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:21:38.362 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
15:21:38.366 INFO  ProgressMeter - Starting traversal
15:21:38.366 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:21:39.376 INFO  ProgressMeter -           20:9944766              0.0                131821        7830950.5
15:21:39.377 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
15:21:39.382 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
15:21:39.387 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
15:21:39.391 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
15:21:39.412 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:21:39.415 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:21:39.415 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:39.653 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:39.759 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
15:21:39.867 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
15:21:39.976 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
15:21:40.085 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
15:21:40.175 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
15:21:40.263 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
15:21:40.357 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
15:21:40.447 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
15:21:40.538 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
15:21:40.628 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
15:21:40.700 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
15:21:40.707 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:21:40.778 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
15:21:40.778 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:40.780 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:40.780 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
15:21:40.781 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:21:40.967 INFO  TrancheManager - Finding 4 tranches for 131821 variants
15:21:40.999 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:21:41.004 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
15:21:41.004 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]
15:21:41.005 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:21:41.009 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
15:21:41.009 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]
15:21:41.010 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:21:41.014 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
15:21:41.014 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]
15:21:41.014 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:21:41.019 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
15:21:41.019 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]
15:21:41.020 INFO  VariantRecalibrator - Writing out recalibration table...
15:21:41.557 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:21:41 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
15:21:41.651 INFO  gatk - Initializing VQSR tests/resetting random number generator
15:21:41.687 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:41.687 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:21:41.687 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:21:41.687 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:21:41.687 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:21:41.687 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:21:41 PM GMT
15:21:41.687 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:41.687 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:41.688 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:21:41.688 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:21:41.688 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:21:41.688 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:21:41.688 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:21:41.688 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:21:41.688 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:21:41.688 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:21:41.688 INFO  VariantRecalibrator - Inflater: IntelInflater
15:21:41.688 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:21:41.689 INFO  VariantRecalibrator - Requester pays: disabled
15:21:41.689 INFO  VariantRecalibrator - Initializing engine
15:21:41.690 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
15:21:41.694 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
15:21:41.697 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
15:21:41.703 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
15:21:41.708 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
15:21:41.710 INFO  VariantRecalibrator - Done initializing engine
15:21:41.710 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
15:21:41.710 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:21:41.710 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
15:21:41.712 INFO  ProgressMeter - Starting traversal
15:21:41.712 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:21:42.660 INFO  ProgressMeter -           20:9944766              0.0                131821        8343101.3
15:21:42.660 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
15:21:42.663 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
15:21:42.668 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
15:21:42.670 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
15:21:42.694 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:21:42.697 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:21:42.697 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:42.937 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:43.044 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
15:21:43.152 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
15:21:43.239 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
15:21:43.328 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
15:21:43.418 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
15:21:43.505 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
15:21:43.596 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
15:21:43.686 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
15:21:43.777 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
15:21:43.867 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
15:21:43.948 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
15:21:43.955 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:21:44.028 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
15:21:44.028 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:44.030 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:44.030 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
15:21:44.032 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:21:44.216 INFO  TrancheManager - Finding 4 tranches for 131821 variants
15:21:44.247 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:21:44.252 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
15:21:44.252 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]
15:21:44.252 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:21:44.256 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
15:21:44.257 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]
15:21:44.257 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:21:44.261 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
15:21:44.261 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]
15:21:44.261 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:21:44.266 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
15:21:44.266 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]
15:21:44.266 INFO  VariantRecalibrator - Writing out recalibration table...
15:21:44.560 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:21:44 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
15:21:44.584 INFO  gatk - Initializing VQSR tests/resetting random number generator
15:21:44.612 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:44.612 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:21:44.612 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:21:44.612 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:21:44.612 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:21:44.612 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:21:44 PM GMT
15:21:44.613 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:44.613 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:44.613 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:21:44.613 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:21:44.613 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:21:44.613 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:21:44.613 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:21:44.613 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:21:44.613 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:21:44.613 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:21:44.613 INFO  VariantRecalibrator - Inflater: IntelInflater
15:21:44.614 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:21:44.614 INFO  VariantRecalibrator - Requester pays: disabled
15:21:44.614 INFO  VariantRecalibrator - Initializing engine
15:21:44.615 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
15:21:44.627 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
15:21:44.666 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
15:21:44.683 INFO  VariantRecalibrator - Done initializing engine
15:21:44.683 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:21:44.696 INFO  ProgressMeter - Starting traversal
15:21:44.696 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:21:44.758 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        2700967.7
15:21:44.758 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
15:21:44.759 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
15:21:44.759 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
15:21:44.759 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
15:21:44.759 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
15:21:44.760 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
15:21:44.760 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
15:21:44.760 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:44.788 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:44.804 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
15:21:44.820 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
15:21:44.836 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
15:21:44.852 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
15:21:44.868 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
15:21:44.884 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
15:21:44.899 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
15:21:44.915 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
15:21:44.931 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
15:21:44.946 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
15:21:44.963 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
15:21:44.978 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
15:21:44.979 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
15:21:44.980 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:21:44.996 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
15:21:44.996 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:44.996 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:44.996 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
15:21:44.996 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:21:45.012 INFO  TrancheManager - Finding 4 tranches for 2786 variants
15:21:45.014 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:21:45.015 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
15:21:45.015 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]
15:21:45.015 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:21:45.015 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
15:21:45.015 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]
15:21:45.015 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:21:45.015 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
15:21:45.015 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]
15:21:45.015 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:21:45.016 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
15:21:45.016 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]
15:21:45.016 INFO  VariantRecalibrator - Writing out recalibration table...
15:21:45.050 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:21:45 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
15:21:45.055 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 3:21:47 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
15:21:47.543 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:47.543 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:21:47.543 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:21:47.543 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:21:47.544 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:21:47.544 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:21:47 PM GMT
15:21:47.544 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:47.544 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:47.544 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:21:47.544 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:21:47.544 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:21:47.544 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:21:47.544 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:21:47.544 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:21:47.544 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:21:47.544 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:21:47.544 INFO  VariantRecalibrator - Inflater: IntelInflater
15:21:47.545 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:21:47.545 INFO  VariantRecalibrator - Requester pays: disabled
15:21:47.545 INFO  VariantRecalibrator - Initializing engine
15:21:47.546 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
15:21:47.549 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
15:21:47.551 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
15:21:47.553 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
15:21:47.556 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/g94982_20_1m_10m_python_2dcnn.indels.vcf.gz
15:21:47.580 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
15:21:47.581 INFO  VariantRecalibrator - Done initializing engine
15:21:47.581 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
15:21:47.581 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:21:47.582 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
15:21:47.585 INFO  ProgressMeter - Starting traversal
15:21:47.585 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:21:48.636 INFO  ProgressMeter -           20:9938789              0.0                134919        7702321.6
15:21:48.636 INFO  ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
15:21:48.639 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
15:21:48.643 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
15:21:48.646 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
15:21:48.668 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:21:48.670 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:21:48.670 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:48.861 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:48.942 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.13181
15:21:49.024 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.46782
15:21:49.108 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 9.04961
15:21:49.193 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.04477
15:21:49.279 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01711
15:21:49.368 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.02053
15:21:49.437 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.01194
15:21:49.505 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.01038
15:21:49.575 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.06192
15:21:49.644 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01281
15:21:49.715 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00457
15:21:49.744 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
15:21:49.749 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
15:21:49.861 INFO  VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
15:21:49.862 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:49.864 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:49.865 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.05287
15:21:49.866 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.02030
15:21:49.868 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.00986
15:21:49.869 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.00749
15:21:49.870 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.00850
15:21:49.872 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01430
15:21:49.873 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02541
15:21:49.874 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.02173
15:21:49.875 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.01024
15:21:49.877 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00479
15:21:49.878 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00245
15:21:49.878 INFO  VariantRecalibratorEngine - Convergence after 57 iterations!
15:21:49.880 INFO  VariantRecalibratorEngine - Evaluating full set of 134603 variants...
15:21:50.070 INFO  TrancheManager - Finding 4 tranches for 134603 variants
15:21:50.108 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:21:50.113 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
15:21:50.113 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]
15:21:50.113 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:21:50.118 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001 
15:21:50.118 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]
15:21:50.118 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:21:50.122 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010 
15:21:50.122 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]
15:21:50.122 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:21:50.126 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100 
15:21:50.127 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]
15:21:50.127 INFO  VariantRecalibrator - Writing out recalibration table...
15:21:50.436 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:21:50 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
15:21:50.438 INFO  gatk - Initializing VQSR tests/resetting random number generator
15:21:50.459 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:50.459 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:21:50.459 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:21:50.459 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:21:50.459 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:21:50.459 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:21:50 PM GMT
15:21:50.459 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:50.459 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:50.459 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:21:50.459 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:21:50.460 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:21:50.460 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:21:50.460 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:21:50.460 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:21:50.460 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:21:50.460 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:21:50.460 INFO  VariantRecalibrator - Inflater: IntelInflater
15:21:50.460 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:21:50.460 INFO  VariantRecalibrator - Requester pays: disabled
15:21:50.460 INFO  VariantRecalibrator - Initializing engine
15:21:50.461 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
15:21:50.463 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
15:21:50.464 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
15:21:50.466 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
15:21:50.470 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
15:21:50.471 INFO  VariantRecalibrator - Done initializing engine
15:21:50.471 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
15:21:50.471 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:21:50.471 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
15:21:50.472 INFO  ProgressMeter - Starting traversal
15:21:50.472 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:21:51.396 INFO  ProgressMeter -           20:9944766              0.0                131821        8559805.2
15:21:51.396 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
15:21:51.398 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
15:21:51.401 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
15:21:51.403 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
15:21:51.425 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:21:51.426 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:21:51.426 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:51.663 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:51.768 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
15:21:51.875 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
15:21:51.984 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
15:21:52.096 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
15:21:52.185 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
15:21:52.273 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
15:21:52.362 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
15:21:52.453 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
15:21:52.542 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
15:21:52.633 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
15:21:52.705 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
15:21:52.712 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:21:52.785 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
15:21:52.785 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:52.787 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:52.787 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
15:21:52.789 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:21:52.971 INFO  TrancheManager - Finding 12 tranches for 131821 variants
15:21:53.008 INFO  TrancheManager -   VQSLODTranche threshold 10.00 => selection metric threshold 0.900
15:21:53.018 INFO  TrancheManager -   Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262 
15:21:53.018 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
15:21:53.018 INFO  TrancheManager -   VQSLODTranche threshold 8.00 => selection metric threshold 0.920
15:21:53.023 INFO  TrancheManager -   Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114 
15:21:53.023 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
15:21:53.023 INFO  TrancheManager -   VQSLODTranche threshold 6.00 => selection metric threshold 0.940
15:21:53.028 INFO  TrancheManager -   Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052 
15:21:53.028 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
15:21:53.028 INFO  TrancheManager -   VQSLODTranche threshold 4.00 => selection metric threshold 0.960
15:21:53.033 INFO  TrancheManager -   Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023 
15:21:53.033 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
15:21:53.033 INFO  TrancheManager -   VQSLODTranche threshold 2.00 => selection metric threshold 0.980
15:21:53.037 INFO  TrancheManager -   Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009 
15:21:53.037 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
15:21:53.037 INFO  TrancheManager -   VQSLODTranche threshold 0.00 => selection metric threshold 1.000
15:21:53.042 INFO  TrancheManager -   Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004 
15:21:53.042 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
15:21:53.042 INFO  TrancheManager -   VQSLODTranche threshold -2.00 => selection metric threshold 1.020
15:21:53.046 INFO  TrancheManager -   Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001 
15:21:53.046 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
15:21:53.046 INFO  TrancheManager -   VQSLODTranche threshold -4.00 => selection metric threshold 1.040
15:21:53.051 INFO  TrancheManager -   Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001 
15:21:53.051 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
15:21:53.051 INFO  TrancheManager -   VQSLODTranche threshold -6.00 => selection metric threshold 1.060
15:21:53.055 INFO  TrancheManager -   Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001 
15:21:53.055 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
15:21:53.055 INFO  TrancheManager -   VQSLODTranche threshold -8.00 => selection metric threshold 1.080
15:21:53.059 INFO  TrancheManager -   Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000 
15:21:53.059 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
15:21:53.059 INFO  TrancheManager -   VQSLODTranche threshold -10.00 => selection metric threshold 1.100
15:21:53.064 INFO  TrancheManager -   Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000 
15:21:53.064 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
15:21:53.064 INFO  TrancheManager -   VQSLODTranche threshold -12.00 => selection metric threshold 1.120
15:21:53.068 INFO  TrancheManager -   Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000 
15:21:53.068 INFO  TrancheManager -   VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
15:21:53.068 INFO  VariantRecalibrator - Writing out recalibration table...
15:21:53.378 INFO  VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
15:21:53.385 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:21:53 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
15:21:53.409 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 3:21:54 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
15:21:54.980 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:54.980 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:21:54.981 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:21:54.981 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:21:54.981 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:21:54.981 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:21:54 PM GMT
15:21:54.981 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:54.981 INFO  VariantRecalibrator - ------------------------------------------------------------
15:21:54.981 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:21:54.981 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:21:54.981 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:21:54.981 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:21:54.981 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:21:54.981 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:21:54.981 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:21:54.981 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:21:54.981 INFO  VariantRecalibrator - Inflater: IntelInflater
15:21:54.981 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:21:54.981 INFO  VariantRecalibrator - Requester pays: disabled
15:21:54.981 INFO  VariantRecalibrator - Initializing engine
15:21:54.983 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
15:21:55.001 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
15:21:55.060 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
15:21:55.084 INFO  VariantRecalibrator - Done initializing engine
15:21:55.085 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:21:55.102 INFO  ProgressMeter - Starting traversal
15:21:55.102 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:21:55.208 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        1579811.3
15:21:55.208 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
15:21:55.208 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
15:21:55.209 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
15:21:55.209 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
15:21:55.209 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
15:21:55.209 INFO  VariantDataManager - AS_FS: 	 mean = 1.08	 standard deviation = 2.43
15:21:55.209 INFO  VariantDataManager - AS_MQRankSum: 	 mean = 0.00	 standard deviation = 0.01
15:21:55.210 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
15:21:55.210 INFO  VariantDataManager - Training with 2769 variants after standard deviation thresholding.
15:21:55.210 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:55.242 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:55.265 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.56007
15:21:55.288 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.67355
15:21:55.312 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 5.08559
15:21:55.336 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.01567
15:21:55.360 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.02021
15:21:55.384 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.01989
15:21:55.408 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.02504
15:21:55.432 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03657
15:21:55.457 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.04057
15:21:55.481 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.08648
15:21:55.506 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.01514
15:21:55.530 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00496
15:21:55.554 INFO  VariantRecalibratorEngine - Finished iteration 65. 	Current change in mixture coefficients = 0.00163
15:21:55.554 INFO  VariantRecalibratorEngine - Convergence after 65 iterations!
15:21:55.557 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:21:55.577 INFO  VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
15:21:55.577 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:21:55.577 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:21:55.577 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
15:21:55.577 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:21:55.591 INFO  TrancheManager - Finding 4 tranches for 2786 variants
15:21:55.592 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:21:55.592 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
15:21:55.592 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]
15:21:55.592 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:21:55.592 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
15:21:55.592 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]
15:21:55.592 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:21:55.592 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
15:21:55.592 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]
15:21:55.592 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:21:55.593 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
15:21:55.593 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]
15:21:55.593 INFO  VariantRecalibrator - Writing out recalibration table...
15:21:55.609 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:21:55 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
15:21:55.611 INFO  gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 3:21:57 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 3:21:58 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 3:21:58 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 3:21:58 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 3:21:59 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 3:22:00 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
15:22:00.746 INFO  VariantRecalibrator - ------------------------------------------------------------
15:22:00.746 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:22:00.746 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:22:00.746 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:22:00.746 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:22:00.746 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:22:00 PM GMT
15:22:00.746 INFO  VariantRecalibrator - ------------------------------------------------------------
15:22:00.746 INFO  VariantRecalibrator - ------------------------------------------------------------
15:22:00.746 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:22:00.746 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:22:00.746 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:22:00.747 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:22:00.747 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:22:00.747 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:22:00.747 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:22:00.747 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:22:00.747 INFO  VariantRecalibrator - Inflater: IntelInflater
15:22:00.747 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:22:00.747 INFO  VariantRecalibrator - Requester pays: disabled
15:22:00.747 INFO  VariantRecalibrator - Initializing engine
15:22:00.748 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
15:22:00.750 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
15:22:00.751 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
15:22:00.753 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
15:22:00.755 INFO  IntervalArgumentCollection - Processing 9000001 bp from intervals
15:22:00.756 INFO  VariantRecalibrator - Done initializing engine
15:22:00.756 INFO  TrainingSet - Found known track: 	Known = true 	Training = false 	Truth = false 	Prior = Q10.0
15:22:00.756 INFO  TrainingSet - Found truth_training1 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:22:00.756 INFO  TrainingSet - Found truth_training2 track: 	Known = false 	Training = true 	Truth = true 	Prior = Q12.0
15:22:00.757 INFO  ProgressMeter - Starting traversal
15:22:00.757 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:22:01.718 INFO  ProgressMeter -           20:9944766              0.0                131821        8230239.3
15:22:01.718 INFO  ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
15:22:01.721 INFO  VariantDataManager - QD: 	 mean = 16.58	 standard deviation = 5.43
15:22:01.726 INFO  VariantDataManager - HaplotypeScore: 	 mean = 0.27	 standard deviation = 0.27
15:22:01.729 INFO  VariantDataManager - HRun: 	 mean = 0.59	 standard deviation = 0.99
15:22:01.752 INFO  VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:22:01.754 INFO  VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:22:01.754 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:22:01.992 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:22:02.109 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.42302
15:22:02.194 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.24203
15:22:02.280 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.15214
15:22:02.368 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.22858
15:22:02.457 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.07799
15:22:02.545 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.04227
15:22:02.636 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00976
15:22:02.727 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.03859
15:22:02.818 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.18953
15:22:02.910 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.01049
15:22:02.990 INFO  VariantRecalibratorEngine - Convergence after 54 iterations!
15:22:02.997 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:22:03.067 INFO  VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
15:22:03.067 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:22:03.068 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:22:03.069 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
15:22:03.070 INFO  VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:22:03.247 INFO  TrancheManager - Finding 12 tranches for 131821 variants
15:22:03.279 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:22:03.283 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
15:22:03.283 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]
15:22:03.283 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
15:22:03.288 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001 
15:22:03.288 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]
15:22:03.288 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:22:03.292 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001 
15:22:03.292 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]
15:22:03.292 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
15:22:03.296 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002 
15:22:03.296 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]
15:22:03.296 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
15:22:03.300 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004 
15:22:03.300 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]
15:22:03.300 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
15:22:03.305 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005 
15:22:03.305 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]
15:22:03.305 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
15:22:03.309 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006 
15:22:03.309 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]
15:22:03.309 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
15:22:03.313 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007 
15:22:03.313 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]
15:22:03.313 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:22:03.317 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010 
15:22:03.318 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]
15:22:03.318 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
15:22:03.322 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020 
15:22:03.322 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]
15:22:03.322 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
15:22:03.326 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030 
15:22:03.326 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]
15:22:03.326 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:22:03.330 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100 
15:22:03.330 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]
15:22:03.331 INFO  VariantRecalibrator - Writing out recalibration table...
15:22:03.624 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:22:03 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
15:22:03.646 INFO  gatk - Initializing VQSR tests/resetting random number generator
15:22:03.664 INFO  VariantRecalibrator - ------------------------------------------------------------
15:22:03.664 INFO  VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g93cf621-SNAPSHOT
15:22:03.664 INFO  VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:22:03.664 INFO  VariantRecalibrator - Executing as root@07a40c7a9995 on Linux v6.11.0-1014-azure amd64
15:22:03.664 INFO  VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
15:22:03.664 INFO  VariantRecalibrator - Start Date/Time: May 27, 2025 at 3:22:03 PM GMT
15:22:03.664 INFO  VariantRecalibrator - ------------------------------------------------------------
15:22:03.664 INFO  VariantRecalibrator - ------------------------------------------------------------
15:22:03.664 INFO  VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
15:22:03.664 INFO  VariantRecalibrator - Picard Version: 3.4.0
15:22:03.664 INFO  VariantRecalibrator - Built for Spark Version: 3.5.0
15:22:03.664 INFO  VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:22:03.664 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:22:03.664 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:22:03.664 INFO  VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:22:03.665 INFO  VariantRecalibrator - Deflater: IntelDeflater
15:22:03.665 INFO  VariantRecalibrator - Inflater: IntelInflater
15:22:03.665 INFO  VariantRecalibrator - GCS max retries/reopens: 20
15:22:03.665 INFO  VariantRecalibrator - Requester pays: disabled
15:22:03.665 INFO  VariantRecalibrator - Initializing engine
15:22:03.666 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
15:22:03.676 INFO  FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
15:22:03.709 INFO  IntervalArgumentCollection - Processing 10000000 bp from intervals
15:22:03.721 INFO  VariantRecalibrator - Done initializing engine
15:22:03.721 INFO  TrainingSet - Found same track: 	Known = false 	Training = true 	Truth = true 	Prior = Q15.0
15:22:03.731 INFO  ProgressMeter - Starting traversal
15:22:03.731 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
15:22:03.786 INFO  ProgressMeter -         chr1:6212018              0.0                  2791        3044727.3
15:22:03.786 INFO  ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
15:22:03.786 INFO  VariantDataManager - AS_QD: 	 mean = 20.88	 standard deviation = 8.12
15:22:03.786 INFO  VariantDataManager - AS_ReadPosRankSum: 	 mean = -0.05	 standard deviation = 0.74
15:22:03.786 INFO  VariantDataManager - AS_MQ: 	 mean = 59.82	 standard deviation = 2.48
15:22:03.786 INFO  VariantDataManager - AS_SOR: 	 mean = 0.86	 standard deviation = 0.67
15:22:03.787 INFO  VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
15:22:03.787 INFO  VariantDataManager - Training with 2774 variants after standard deviation thresholding.
15:22:03.787 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:22:03.815 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:22:03.831 INFO  VariantRecalibratorEngine - Finished iteration 5. 	Current change in mixture coefficients = 0.12046
15:22:03.847 INFO  VariantRecalibratorEngine - Finished iteration 10. 	Current change in mixture coefficients = 0.09714
15:22:03.863 INFO  VariantRecalibratorEngine - Finished iteration 15. 	Current change in mixture coefficients = 0.07781
15:22:03.878 INFO  VariantRecalibratorEngine - Finished iteration 20. 	Current change in mixture coefficients = 0.05863
15:22:03.894 INFO  VariantRecalibratorEngine - Finished iteration 25. 	Current change in mixture coefficients = 0.01774
15:22:03.910 INFO  VariantRecalibratorEngine - Finished iteration 30. 	Current change in mixture coefficients = 0.00612
15:22:03.926 INFO  VariantRecalibratorEngine - Finished iteration 35. 	Current change in mixture coefficients = 0.00395
15:22:03.942 INFO  VariantRecalibratorEngine - Finished iteration 40. 	Current change in mixture coefficients = 0.00313
15:22:03.958 INFO  VariantRecalibratorEngine - Finished iteration 45. 	Current change in mixture coefficients = 0.00276
15:22:03.974 INFO  VariantRecalibratorEngine - Finished iteration 50. 	Current change in mixture coefficients = 0.00245
15:22:03.990 INFO  VariantRecalibratorEngine - Finished iteration 55. 	Current change in mixture coefficients = 0.00219
15:22:04.006 INFO  VariantRecalibratorEngine - Finished iteration 60. 	Current change in mixture coefficients = 0.00198
15:22:04.006 INFO  VariantRecalibratorEngine - Convergence after 60 iterations!
15:22:04.008 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:22:04.018 INFO  VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
15:22:04.018 INFO  GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:22:04.018 INFO  VariantRecalibratorEngine - Finished iteration 0.
15:22:04.018 INFO  VariantRecalibratorEngine - Convergence after 3 iterations!
15:22:04.019 INFO  VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:22:04.026 INFO  TrancheManager - Finding 12 tranches for 2786 variants
15:22:04.027 INFO  TrancheManager -   TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:22:04.027 INFO  TrancheManager -   Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 
15:22:04.027 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]
15:22:04.027 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
15:22:04.027 INFO  TrancheManager -   Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001 
15:22:04.027 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]
15:22:04.027 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:22:04.028 INFO  TrancheManager -   Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001 
15:22:04.028 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]
15:22:04.028 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
15:22:04.028 INFO  TrancheManager -   Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002 
15:22:04.028 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]
15:22:04.028 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
15:22:04.028 INFO  TrancheManager -   Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004 
15:22:04.028 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]
15:22:04.028 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
15:22:04.028 INFO  TrancheManager -   Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005 
15:22:04.028 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]
15:22:04.028 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
15:22:04.029 INFO  TrancheManager -   Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006 
15:22:04.029 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]
15:22:04.029 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
15:22:04.029 INFO  TrancheManager -   Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007 
15:22:04.029 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]
15:22:04.029 INFO  TrancheManager -   TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:22:04.029 INFO  TrancheManager -   Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010 
15:22:04.029 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]
15:22:04.029 INFO  TrancheManager -   TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
15:22:04.029 INFO  TrancheManager -   Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020 
15:22:04.029 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]
15:22:04.029 INFO  TrancheManager -   TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
15:22:04.029 INFO  TrancheManager -   Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030 
15:22:04.029 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]
15:22:04.029 INFO  TrancheManager -   TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:22:04.029 INFO  TrancheManager -   Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100 
15:22:04.029 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]
15:22:04.030 INFO  VariantRecalibrator - Writing out recalibration table...
15:22:04.042 INFO  VariantRecalibrator - Shutting down engine
[May 27, 2025 at 3:22:04 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[May 27, 2025 at 3:23:03 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000