[May 27, 2025 at 6:42:16 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.09 minutes.
Runtime.totalMemory()=1048576000
18:42:16.680 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:16.680 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:16.680 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:16.681 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:16.681 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:16.681 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:16 PM GMT
18:42:16.681 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:16.681 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:16.681 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:16.682 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:16.682 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:16.682 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:16.682 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:16.682 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:16.682 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:16.682 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:16.682 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:16.682 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:16.682 INFO VariantRecalibrator - Requester pays: disabled
18:42:16.683 INFO VariantRecalibrator - Initializing engine
18:42:16.686 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
18:42:16.716 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
18:42:16.822 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
18:42:16.860 INFO VariantRecalibrator - Done initializing engine
18:42:16.861 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
18:42:16.898 INFO ProgressMeter - Starting traversal
18:42:16.899 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:17.039 INFO ProgressMeter - chr1:6212018 0.0 2791 1196142.9
18:42:17.040 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
18:42:17.041 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
18:42:17.042 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
18:42:17.043 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
18:42:17.044 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
18:42:17.050 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
18:42:17.051 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
18:42:17.051 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:17.108 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:17.132 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.16919
18:42:17.150 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.14268
18:42:17.172 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.19617
18:42:17.201 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.09047
18:42:17.219 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.05235
18:42:17.237 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04028
18:42:17.255 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02103
18:42:17.273 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01461
18:42:17.291 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01136
18:42:17.309 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00583
18:42:17.328 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00291
18:42:17.338 INFO VariantRecalibratorEngine - Convergence after 58 iterations!
18:42:17.341 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
18:42:17.358 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
18:42:17.369 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:17 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
18:42:17.374 INFO gatk - Initializing VQSR tests/resetting random number generator
18:42:17.409 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:17.409 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:17.409 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:17.409 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:17.409 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:17.410 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:17 PM GMT
18:42:17.410 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:17.410 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:17.410 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:17.410 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:17.410 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:17.410 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:17.411 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:17.411 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:17.411 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:17.411 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:17.411 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:17.411 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:17.411 INFO VariantRecalibrator - Requester pays: disabled
18:42:17.411 INFO VariantRecalibrator - Initializing engine
18:42:17.414 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
18:42:17.420 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
18:42:17.424 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
18:42:17.428 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
18:42:17.435 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
18:42:17.437 INFO VariantRecalibrator - Done initializing engine
18:42:17.439 WARN VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
18:42:17.440 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
18:42:17.440 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
18:42:17.440 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
18:42:17.444 INFO ProgressMeter - Starting traversal
18:42:17.444 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:18.608 INFO ProgressMeter - 20:9944766 0.0 131821 6800739.5
18:42:18.608 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
18:42:18.616 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
18:42:18.627 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
18:42:18.637 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
18:42:18.693 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
18:42:18.696 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
18:42:18.696 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:18.969 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:19.083 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
18:42:19.196 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
18:42:19.322 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
18:42:19.439 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
18:42:19.551 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
18:42:19.661 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
18:42:19.774 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
18:42:19.887 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
18:42:20.006 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
18:42:20.105 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
18:42:20.180 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
18:42:20.187 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
18:42:20.260 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
18:42:20.260 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:20.262 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:20.263 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
18:42:20.266 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
18:42:20.450 INFO TrancheManager - Finding 4 tranches for 131821 variants
18:42:20.486 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
18:42:20.497 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
18:42:20.497 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]
18:42:20.498 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
18:42:20.508 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
18:42:20.508 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]
18:42:20.509 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
18:42:20.519 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
18:42:20.519 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]
18:42:20.519 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
18:42:20.535 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
18:42:20.535 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]
18:42:20.536 INFO VariantRecalibrator - Writing out recalibration table...
18:42:21.033 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:21 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1153433600
18:42:21.108 INFO gatk - Initializing VQSR tests/resetting random number generator
18:42:21.142 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:21.142 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:21.142 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:21.142 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:21.142 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:21.142 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:21 PM GMT
18:42:21.143 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:21.143 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:21.143 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:21.143 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:21.143 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:21.143 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:21.143 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:21.143 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:21.144 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:21.144 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:21.144 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:21.144 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:21.144 INFO VariantRecalibrator - Requester pays: disabled
18:42:21.144 INFO VariantRecalibrator - Initializing engine
18:42:21.146 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
18:42:21.150 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
18:42:21.153 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
18:42:21.160 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
18:42:21.165 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
18:42:21.167 INFO VariantRecalibrator - Done initializing engine
18:42:21.167 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
18:42:21.167 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
18:42:21.167 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
18:42:21.170 INFO ProgressMeter - Starting traversal
18:42:21.170 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:22.155 INFO ProgressMeter - 20:9944766 0.0 131821 8029705.6
18:42:22.156 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
18:42:22.159 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
18:42:22.165 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
18:42:22.170 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
18:42:22.202 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
18:42:22.204 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
18:42:22.204 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:22.458 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:22.566 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
18:42:22.684 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
18:42:22.771 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
18:42:22.858 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
18:42:22.947 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
18:42:23.036 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
18:42:23.127 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
18:42:23.218 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
18:42:23.311 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
18:42:23.402 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
18:42:23.475 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
18:42:23.482 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
18:42:23.553 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
18:42:23.554 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:23.555 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:23.556 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
18:42:23.558 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
18:42:23.750 INFO TrancheManager - Finding 4 tranches for 131821 variants
18:42:23.789 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
18:42:23.796 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
18:42:23.797 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]
18:42:23.797 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
18:42:23.811 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
18:42:23.811 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]
18:42:23.811 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
18:42:23.828 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
18:42:23.829 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]
18:42:23.829 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
18:42:23.842 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
18:42:23.843 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]
18:42:23.843 INFO VariantRecalibrator - Writing out recalibration table...
18:42:24.161 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:24 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1153433600
18:42:24.185 INFO gatk - Initializing VQSR tests/resetting random number generator
18:42:24.213 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:24.213 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:24.213 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:24.213 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:24.213 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:24.214 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:24 PM GMT
18:42:24.214 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:24.214 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:24.214 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:24.214 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:24.214 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:24.214 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:24.214 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:24.215 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:24.215 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:24.215 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:24.215 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:24.215 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:24.215 INFO VariantRecalibrator - Requester pays: disabled
18:42:24.215 INFO VariantRecalibrator - Initializing engine
18:42:24.217 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
18:42:24.235 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
18:42:24.281 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
18:42:24.299 INFO VariantRecalibrator - Done initializing engine
18:42:24.300 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
18:42:24.314 INFO ProgressMeter - Starting traversal
18:42:24.314 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:24.365 INFO ProgressMeter - chr1:6212018 0.0 2791 3283529.4
18:42:24.366 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
18:42:24.366 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
18:42:24.366 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
18:42:24.366 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
18:42:24.366 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
18:42:24.367 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
18:42:24.367 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
18:42:24.368 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:24.420 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:24.448 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
18:42:24.477 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
18:42:24.505 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
18:42:24.534 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
18:42:24.562 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
18:42:24.586 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
18:42:24.604 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
18:42:24.621 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
18:42:24.639 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
18:42:24.657 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
18:42:24.675 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
18:42:24.692 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
18:42:24.692 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
18:42:24.694 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
18:42:24.711 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
18:42:24.711 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:24.711 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:24.711 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
18:42:24.712 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
18:42:24.729 INFO TrancheManager - Finding 4 tranches for 2786 variants
18:42:24.731 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
18:42:24.731 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
18:42:24.731 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]
18:42:24.731 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
18:42:24.731 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
18:42:24.732 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]
18:42:24.732 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
18:42:24.732 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
18:42:24.732 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]
18:42:24.732 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
18:42:24.732 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
18:42:24.732 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]
18:42:24.733 INFO VariantRecalibrator - Writing out recalibration table...
18:42:24.773 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:24 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1153433600
18:42:24.778 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 6:42:27 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1153433600
18:42:27.526 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:27.527 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:27.527 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:27.527 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:27.527 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:27.527 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:27 PM GMT
18:42:27.527 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:27.527 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:27.527 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:27.527 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:27.527 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:27.527 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:27.528 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:27.528 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:27.528 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:27.528 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:27.528 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:27.528 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:27.528 INFO VariantRecalibrator - Requester pays: disabled
18:42:27.528 INFO VariantRecalibrator - Initializing engine
18:42:27.530 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
18:42:27.533 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
18:42:27.535 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
18:42:27.538 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
18:42:27.540 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/g94982_20_1m_10m_python_2dcnn.indels.vcf.gz
18:42:27.561 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
18:42:27.563 INFO VariantRecalibrator - Done initializing engine
18:42:27.563 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
18:42:27.563 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
18:42:27.563 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
18:42:27.567 INFO ProgressMeter - Starting traversal
18:42:27.567 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:28.624 INFO ProgressMeter - 20:9938789 0.0 134919 7658599.8
18:42:28.625 INFO ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
18:42:28.628 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
18:42:28.635 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
18:42:28.641 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
18:42:28.674 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
18:42:28.677 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
18:42:28.677 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:28.912 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:29.082 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.13181
18:42:29.244 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.46782
18:42:29.355 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 9.04961
18:42:29.485 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.04477
18:42:29.598 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01711
18:42:29.690 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.02053
18:42:29.779 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.01194
18:42:29.879 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01038
18:42:29.952 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.06192
18:42:30.027 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01281
18:42:30.104 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00457
18:42:30.136 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
18:42:30.142 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
18:42:30.264 INFO VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
18:42:30.264 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:30.267 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:30.268 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.05287
18:42:30.269 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.02030
18:42:30.271 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.00986
18:42:30.272 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.00749
18:42:30.273 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.00850
18:42:30.275 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01430
18:42:30.276 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02541
18:42:30.278 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.02173
18:42:30.279 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01024
18:42:30.280 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00479
18:42:30.282 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00245
18:42:30.282 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
18:42:30.285 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
18:42:30.479 INFO TrancheManager - Finding 4 tranches for 134603 variants
18:42:30.536 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
18:42:30.553 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
18:42:30.554 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]
18:42:30.554 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
18:42:30.571 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001
18:42:30.571 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]
18:42:30.571 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
18:42:30.585 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010
18:42:30.585 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]
18:42:30.585 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
18:42:30.598 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100
18:42:30.599 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]
18:42:30.599 INFO VariantRecalibrator - Writing out recalibration table...
18:42:30.939 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:30 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1153433600
18:42:30.942 INFO gatk - Initializing VQSR tests/resetting random number generator
18:42:30.963 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:30.963 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:30.964 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:30.964 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:30.964 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:30.964 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:30 PM GMT
18:42:30.964 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:30.964 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:30.964 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:30.964 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:30.964 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:30.965 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:30.965 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:30.965 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:30.965 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:30.965 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:30.965 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:30.965 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:30.965 INFO VariantRecalibrator - Requester pays: disabled
18:42:30.965 INFO VariantRecalibrator - Initializing engine
18:42:30.966 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
18:42:30.968 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
18:42:30.970 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
18:42:30.972 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
18:42:30.974 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
18:42:30.975 INFO VariantRecalibrator - Done initializing engine
18:42:30.976 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
18:42:30.976 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
18:42:30.976 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
18:42:30.977 INFO ProgressMeter - Starting traversal
18:42:30.977 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:32.006 INFO ProgressMeter - 20:9944766 0.0 131821 7686355.7
18:42:32.006 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
18:42:32.009 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
18:42:32.017 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
18:42:32.023 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
18:42:32.060 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
18:42:32.062 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
18:42:32.063 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:32.338 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:32.458 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
18:42:32.572 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
18:42:32.667 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
18:42:32.764 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
18:42:32.862 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
18:42:32.959 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
18:42:33.059 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
18:42:33.156 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
18:42:33.254 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
18:42:33.353 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
18:42:33.431 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
18:42:33.438 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
18:42:33.525 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
18:42:33.525 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:33.526 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:33.527 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
18:42:33.529 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
18:42:33.731 INFO TrancheManager - Finding 12 tranches for 131821 variants
18:42:33.773 INFO TrancheManager - VQSLODTranche threshold 10.00 => selection metric threshold 0.900
18:42:33.801 INFO TrancheManager - Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262
18:42:33.801 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
18:42:33.801 INFO TrancheManager - VQSLODTranche threshold 8.00 => selection metric threshold 0.920
18:42:33.828 INFO TrancheManager - Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114
18:42:33.828 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
18:42:33.828 INFO TrancheManager - VQSLODTranche threshold 6.00 => selection metric threshold 0.940
18:42:33.850 INFO TrancheManager - Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052
18:42:33.851 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
18:42:33.851 INFO TrancheManager - VQSLODTranche threshold 4.00 => selection metric threshold 0.960
18:42:33.872 INFO TrancheManager - Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023
18:42:33.873 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
18:42:33.873 INFO TrancheManager - VQSLODTranche threshold 2.00 => selection metric threshold 0.980
18:42:33.893 INFO TrancheManager - Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009
18:42:33.893 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
18:42:33.894 INFO TrancheManager - VQSLODTranche threshold 0.00 => selection metric threshold 1.000
18:42:33.913 INFO TrancheManager - Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004
18:42:33.913 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
18:42:33.913 INFO TrancheManager - VQSLODTranche threshold -2.00 => selection metric threshold 1.020
18:42:33.928 INFO TrancheManager - Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001
18:42:33.929 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
18:42:33.929 INFO TrancheManager - VQSLODTranche threshold -4.00 => selection metric threshold 1.040
18:42:33.935 INFO TrancheManager - Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001
18:42:33.935 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
18:42:33.935 INFO TrancheManager - VQSLODTranche threshold -6.00 => selection metric threshold 1.060
18:42:33.940 INFO TrancheManager - Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001
18:42:33.940 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
18:42:33.940 INFO TrancheManager - VQSLODTranche threshold -8.00 => selection metric threshold 1.080
18:42:33.946 INFO TrancheManager - Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000
18:42:33.946 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
18:42:33.946 INFO TrancheManager - VQSLODTranche threshold -10.00 => selection metric threshold 1.100
18:42:33.954 INFO TrancheManager - Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000
18:42:33.954 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
18:42:33.954 INFO TrancheManager - VQSLODTranche threshold -12.00 => selection metric threshold 1.120
18:42:33.968 INFO TrancheManager - Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000
18:42:33.968 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
18:42:33.969 INFO VariantRecalibrator - Writing out recalibration table...
18:42:34.308 INFO VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
18:42:34.317 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:34 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1153433600
18:42:34.341 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 6:42:35 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1153433600
18:42:35.924 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:35.924 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:35.925 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:35.925 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:35.925 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:35.925 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:35 PM GMT
18:42:35.925 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:35.925 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:35.925 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:35.925 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:35.925 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:35.925 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:35.925 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:35.925 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:35.925 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:35.925 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:35.925 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:35.926 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:35.926 INFO VariantRecalibrator - Requester pays: disabled
18:42:35.926 INFO VariantRecalibrator - Initializing engine
18:42:35.927 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
18:42:35.942 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
18:42:35.989 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
18:42:36.008 INFO VariantRecalibrator - Done initializing engine
18:42:36.008 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
18:42:36.022 INFO ProgressMeter - Starting traversal
18:42:36.022 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:36.082 INFO ProgressMeter - chr1:6212018 0.0 2791 2838305.1
18:42:36.083 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
18:42:36.083 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
18:42:36.083 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
18:42:36.083 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
18:42:36.083 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
18:42:36.083 INFO VariantDataManager - AS_FS: mean = 1.08 standard deviation = 2.43
18:42:36.084 INFO VariantDataManager - AS_MQRankSum: mean = 0.00 standard deviation = 0.01
18:42:36.085 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
18:42:36.085 INFO VariantDataManager - Training with 2769 variants after standard deviation thresholding.
18:42:36.085 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:36.120 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:36.145 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.56007
18:42:36.171 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.67355
18:42:36.199 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 5.08559
18:42:36.228 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.01567
18:42:36.256 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.02021
18:42:36.282 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01989
18:42:36.308 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02504
18:42:36.334 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03657
18:42:36.361 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.04057
18:42:36.387 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.08648
18:42:36.414 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.01514
18:42:36.439 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00496
18:42:36.465 INFO VariantRecalibratorEngine - Finished iteration 65. Current change in mixture coefficients = 0.00163
18:42:36.465 INFO VariantRecalibratorEngine - Convergence after 65 iterations!
18:42:36.468 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
18:42:36.486 INFO VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
18:42:36.487 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:36.487 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:36.487 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
18:42:36.487 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
18:42:36.501 INFO TrancheManager - Finding 4 tranches for 2786 variants
18:42:36.501 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
18:42:36.501 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
18:42:36.501 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]
18:42:36.501 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
18:42:36.502 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
18:42:36.502 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]
18:42:36.502 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
18:42:36.502 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
18:42:36.502 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]
18:42:36.502 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
18:42:36.502 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
18:42:36.502 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]
18:42:36.503 INFO VariantRecalibrator - Writing out recalibration table...
18:42:36.519 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:36 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1153433600
18:42:36.521 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 6:42:39 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1153433600
[May 27, 2025 at 6:42:39 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1153433600
[May 27, 2025 at 6:42:39 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1153433600
[May 27, 2025 at 6:42:39 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1153433600
[May 27, 2025 at 6:42:40 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1153433600
[May 27, 2025 at 6:42:42 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1153433600
18:42:42.367 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:42.367 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:42.367 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:42.367 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:42.367 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:42.367 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:42 PM GMT
18:42:42.367 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:42.368 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:42.368 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:42.368 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:42.368 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:42.368 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:42.368 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:42.368 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:42.368 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:42.368 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:42.368 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:42.368 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:42.368 INFO VariantRecalibrator - Requester pays: disabled
18:42:42.368 INFO VariantRecalibrator - Initializing engine
18:42:42.369 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
18:42:42.372 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
18:42:42.373 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
18:42:42.375 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
18:42:42.377 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
18:42:42.378 INFO VariantRecalibrator - Done initializing engine
18:42:42.378 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
18:42:42.378 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
18:42:42.378 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
18:42:42.379 INFO ProgressMeter - Starting traversal
18:42:42.379 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:43.368 INFO ProgressMeter - 20:9944766 0.0 131821 7997229.5
18:42:43.368 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
18:42:43.373 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
18:42:43.381 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
18:42:43.388 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
18:42:43.425 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
18:42:43.428 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
18:42:43.428 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:43.786 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:44.058 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
18:42:44.216 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
18:42:44.305 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
18:42:44.396 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
18:42:44.487 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
18:42:44.579 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
18:42:44.672 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
18:42:44.766 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
18:42:44.859 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
18:42:44.952 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
18:42:45.027 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
18:42:45.035 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
18:42:45.118 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
18:42:45.118 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:45.120 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:45.120 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
18:42:45.122 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
18:42:45.308 INFO TrancheManager - Finding 12 tranches for 131821 variants
18:42:45.362 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
18:42:45.382 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
18:42:45.382 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]
18:42:45.382 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
18:42:45.402 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001
18:42:45.402 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.95 minVQSLod=-6.6729 known=(59316 @ 2.3020) novel=(72124 @ 2.2259) truthSites(18665 accessible, 18655 called), name=anonymous]
18:42:45.402 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
18:42:45.422 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
18:42:45.422 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]
18:42:45.422 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
18:42:45.442 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002
18:42:45.443 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]
18:42:45.443 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
18:42:45.464 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004
18:42:45.464 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]
18:42:45.464 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
18:42:45.485 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005
18:42:45.485 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]
18:42:45.485 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
18:42:45.506 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006
18:42:45.507 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]
18:42:45.507 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
18:42:45.526 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007
18:42:45.526 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]
18:42:45.526 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
18:42:45.546 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
18:42:45.546 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]
18:42:45.546 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
18:42:45.566 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020
18:42:45.567 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]
18:42:45.567 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
18:42:45.591 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030
18:42:45.591 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]
18:42:45.591 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
18:42:45.612 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
18:42:45.612 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]
18:42:45.612 INFO VariantRecalibrator - Writing out recalibration table...
18:42:45.962 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:45 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1153433600
18:42:45.987 INFO gatk - Initializing VQSR tests/resetting random number generator
18:42:46.014 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:46.015 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-6-g06789f4-SNAPSHOT
18:42:46.015 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
18:42:46.015 INFO VariantRecalibrator - Executing as root@9bb9f17fa524 on Linux v6.11.0-1014-azure amd64
18:42:46.015 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
18:42:46.015 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 6:42:46 PM GMT
18:42:46.015 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:46.015 INFO VariantRecalibrator - ------------------------------------------------------------
18:42:46.015 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
18:42:46.015 INFO VariantRecalibrator - Picard Version: 3.4.0
18:42:46.015 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
18:42:46.015 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
18:42:46.015 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
18:42:46.015 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
18:42:46.016 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
18:42:46.016 INFO VariantRecalibrator - Deflater: IntelDeflater
18:42:46.016 INFO VariantRecalibrator - Inflater: IntelInflater
18:42:46.016 INFO VariantRecalibrator - GCS max retries/reopens: 20
18:42:46.016 INFO VariantRecalibrator - Requester pays: disabled
18:42:46.016 INFO VariantRecalibrator - Initializing engine
18:42:46.018 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
18:42:46.036 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
18:42:46.074 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
18:42:46.090 INFO VariantRecalibrator - Done initializing engine
18:42:46.090 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
18:42:46.101 INFO ProgressMeter - Starting traversal
18:42:46.101 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
18:42:46.152 INFO ProgressMeter - chr1:6212018 0.0 2791 3283529.4
18:42:46.153 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
18:42:46.153 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
18:42:46.153 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
18:42:46.153 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
18:42:46.153 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
18:42:46.154 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
18:42:46.154 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
18:42:46.154 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:46.184 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:46.202 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
18:42:46.219 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
18:42:46.236 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
18:42:46.253 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
18:42:46.271 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
18:42:46.289 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
18:42:46.306 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
18:42:46.323 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
18:42:46.340 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
18:42:46.365 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
18:42:46.380 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
18:42:46.396 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
18:42:46.396 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
18:42:46.398 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
18:42:46.406 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
18:42:46.407 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
18:42:46.407 INFO VariantRecalibratorEngine - Finished iteration 0.
18:42:46.407 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
18:42:46.407 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
18:42:46.415 INFO TrancheManager - Finding 12 tranches for 2786 variants
18:42:46.416 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
18:42:46.416 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
18:42:46.416 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]
18:42:46.416 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
18:42:46.417 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001
18:42:46.417 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]
18:42:46.417 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
18:42:46.417 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
18:42:46.417 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]
18:42:46.417 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
18:42:46.417 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002
18:42:46.417 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]
18:42:46.417 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
18:42:46.417 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004
18:42:46.417 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]
18:42:46.417 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
18:42:46.418 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005
18:42:46.418 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]
18:42:46.418 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
18:42:46.418 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006
18:42:46.418 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]
18:42:46.418 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
18:42:46.418 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007
18:42:46.418 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]
18:42:46.418 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
18:42:46.418 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
18:42:46.418 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]
18:42:46.418 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
18:42:46.418 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020
18:42:46.419 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]
18:42:46.419 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
18:42:46.419 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030
18:42:46.419 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]
18:42:46.419 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
18:42:46.419 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
18:42:46.419 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]
18:42:46.419 INFO VariantRecalibrator - Writing out recalibration table...
18:42:46.433 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 6:42:46 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1153433600
[May 27, 2025 at 6:43:56 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1153433600