[May 19, 2025 at 7:23:25 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
19:23:25.817 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:25.818 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:25.818 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:25.818 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:25.818 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:25.819 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:25 PM GMT
19:23:25.819 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:25.819 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:25.819 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:25.819 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:25.819 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:25.819 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:25.819 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:25.820 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:25.820 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:25.820 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:25.820 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:25.820 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:25.820 INFO VariantRecalibrator - Requester pays: disabled
19:23:25.820 INFO VariantRecalibrator - Initializing engine
19:23:25.824 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
19:23:25.845 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
19:23:25.907 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
19:23:25.929 INFO VariantRecalibrator - Done initializing engine
19:23:25.929 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
19:23:25.954 INFO ProgressMeter - Starting traversal
19:23:25.954 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:26.094 INFO ProgressMeter - chr1:6212018 0.0 2791 1196142.9
19:23:26.095 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
19:23:26.095 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
19:23:26.096 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
19:23:26.096 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
19:23:26.097 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
19:23:26.097 INFO VariantDataManager - AS_FS: mean = 1.08 standard deviation = 2.43
19:23:26.097 INFO VariantDataManager - AS_MQRankSum: mean = 0.00 standard deviation = 0.01
19:23:26.104 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
19:23:26.105 INFO VariantDataManager - Training with 2769 variants after standard deviation thresholding.
19:23:26.105 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:26.158 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:26.201 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.56007
19:23:26.244 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.67355
19:23:26.288 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 5.08559
19:23:26.332 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.01567
19:23:26.376 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.02021
19:23:26.420 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01989
19:23:26.448 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02504
19:23:26.481 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03657
19:23:26.508 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.04057
19:23:26.533 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.08648
19:23:26.559 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.01514
19:23:26.585 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00496
19:23:26.610 INFO VariantRecalibratorEngine - Finished iteration 65. Current change in mixture coefficients = 0.00163
19:23:26.610 INFO VariantRecalibratorEngine - Convergence after 65 iterations!
19:23:26.620 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
19:23:26.663 INFO VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
19:23:26.663 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:26.663 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:26.663 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
19:23:26.664 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
19:23:26.690 INFO TrancheManager - Finding 4 tranches for 2786 variants
19:23:26.691 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
19:23:26.691 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
19:23:26.692 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]
19:23:26.692 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
19:23:26.692 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
19:23:26.692 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]
19:23:26.693 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
19:23:26.693 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
19:23:26.693 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]
19:23:26.693 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
19:23:26.693 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
19:23:26.694 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]
19:23:26.694 INFO VariantRecalibrator - Writing out recalibration table...
19:23:26.742 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:26 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
19:23:26.744 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 7:23:30 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 7:23:32 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
19:23:32.957 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:32.957 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:32.957 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:32.958 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:32.958 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:32.958 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:32 PM GMT
19:23:32.958 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:32.958 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:32.958 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:32.958 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:32.958 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:32.959 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:32.959 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:32.959 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:32.959 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:32.959 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:32.959 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:32.959 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:32.959 INFO VariantRecalibrator - Requester pays: disabled
19:23:32.959 INFO VariantRecalibrator - Initializing engine
19:23:32.961 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
19:23:32.973 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
19:23:33.012 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
19:23:33.028 INFO VariantRecalibrator - Done initializing engine
19:23:33.028 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
19:23:33.041 INFO ProgressMeter - Starting traversal
19:23:33.042 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:33.086 INFO ProgressMeter - chr1:6212018 0.0 2791 3805909.1
19:23:33.087 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
19:23:33.087 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
19:23:33.087 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
19:23:33.087 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
19:23:33.087 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
19:23:33.088 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
19:23:33.088 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
19:23:33.088 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:33.120 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:33.138 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.16919
19:23:33.155 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.14268
19:23:33.172 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.19617
19:23:33.190 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.09047
19:23:33.207 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.05235
19:23:33.225 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04028
19:23:33.242 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02103
19:23:33.259 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01461
19:23:33.277 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01136
19:23:33.299 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00583
19:23:33.315 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00291
19:23:33.325 INFO VariantRecalibratorEngine - Convergence after 58 iterations!
19:23:33.326 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
19:23:33.335 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
19:23:33.341 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:33 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
19:23:33.343 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 7:23:33 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 7:23:33 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 7:23:34 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 7:23:36 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1048576000
19:23:36.168 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:36.168 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:36.168 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:36.169 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:36.169 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:36.169 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:36 PM GMT
19:23:36.169 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:36.169 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:36.169 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:36.169 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:36.169 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:36.169 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:36.169 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:36.170 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:36.170 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:36.170 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:36.170 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:36.170 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:36.170 INFO VariantRecalibrator - Requester pays: disabled
19:23:36.170 INFO VariantRecalibrator - Initializing engine
19:23:36.171 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
19:23:36.173 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
19:23:36.175 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
19:23:36.176 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
19:23:36.179 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
19:23:36.180 INFO VariantRecalibrator - Done initializing engine
19:23:36.182 WARN VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
19:23:36.182 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
19:23:36.182 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
19:23:36.182 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
19:23:36.183 INFO ProgressMeter - Starting traversal
19:23:36.183 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:37.159 INFO ProgressMeter - 20:9944766 0.0 131821 8112061.5
19:23:37.159 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
19:23:37.162 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
19:23:37.164 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
19:23:37.167 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
19:23:37.189 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
19:23:37.190 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
19:23:37.191 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:37.448 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:37.558 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
19:23:37.670 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
19:23:37.783 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
19:23:37.899 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
19:23:38.015 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
19:23:38.107 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
19:23:38.200 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
19:23:38.294 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
19:23:38.387 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
19:23:38.481 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
19:23:38.556 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
19:23:38.563 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
19:23:38.630 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
19:23:38.630 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:38.631 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:38.632 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
19:23:38.633 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
19:23:38.811 INFO TrancheManager - Finding 4 tranches for 131821 variants
19:23:38.843 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
19:23:38.847 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
19:23:38.847 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]
19:23:38.847 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
19:23:38.852 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
19:23:38.852 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]
19:23:38.852 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
19:23:38.856 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
19:23:38.856 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]
19:23:38.856 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
19:23:38.860 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
19:23:38.860 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]
19:23:38.860 INFO VariantRecalibrator - Writing out recalibration table...
19:23:39.151 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:39 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
19:23:39.185 INFO gatk - Initializing VQSR tests/resetting random number generator
19:23:39.203 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:39.203 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:39.203 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:39.203 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:39.203 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:39.204 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:39 PM GMT
19:23:39.204 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:39.204 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:39.204 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:39.204 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:39.204 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:39.204 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:39.204 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:39.204 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:39.204 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:39.204 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:39.204 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:39.205 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:39.205 INFO VariantRecalibrator - Requester pays: disabled
19:23:39.205 INFO VariantRecalibrator - Initializing engine
19:23:39.206 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
19:23:39.209 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
19:23:39.211 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
19:23:39.213 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
19:23:39.217 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
19:23:39.218 INFO VariantRecalibrator - Done initializing engine
19:23:39.218 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
19:23:39.218 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
19:23:39.218 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
19:23:39.219 INFO ProgressMeter - Starting traversal
19:23:39.220 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:40.181 INFO ProgressMeter - 20:9944766 0.0 131821 8230239.3
19:23:40.182 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
19:23:40.184 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
19:23:40.187 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
19:23:40.190 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
19:23:40.214 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
19:23:40.215 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
19:23:40.216 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:40.469 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:40.579 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
19:23:40.690 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
19:23:40.808 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
19:23:40.899 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
19:23:40.991 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
19:23:41.082 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
19:23:41.176 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
19:23:41.269 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
19:23:41.362 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
19:23:41.456 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
19:23:41.531 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
19:23:41.539 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
19:23:41.607 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
19:23:41.607 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:41.609 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:41.610 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
19:23:41.611 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
19:23:41.799 INFO TrancheManager - Finding 4 tranches for 131821 variants
19:23:41.831 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
19:23:41.835 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
19:23:41.835 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-240.7209 known=(59500 @ 2.2991) novel=(72321 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
19:23:41.835 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
19:23:41.839 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
19:23:41.839 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]
19:23:41.839 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
19:23:41.843 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
19:23:41.843 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]
19:23:41.843 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
19:23:41.847 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
19:23:41.847 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]
19:23:41.847 INFO VariantRecalibrator - Writing out recalibration table...
19:23:42.127 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:42 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
19:23:42.150 INFO gatk - Initializing VQSR tests/resetting random number generator
19:23:42.168 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:42.169 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:42.169 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:42.169 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:42.169 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:42.169 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:42 PM GMT
19:23:42.169 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:42.169 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:42.169 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:42.169 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:42.169 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:42.170 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:42.170 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:42.170 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:42.170 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:42.170 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:42.170 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:42.170 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:42.170 INFO VariantRecalibrator - Requester pays: disabled
19:23:42.170 INFO VariantRecalibrator - Initializing engine
19:23:42.171 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
19:23:42.184 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
19:23:42.219 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
19:23:42.234 INFO VariantRecalibrator - Done initializing engine
19:23:42.234 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
19:23:42.245 INFO ProgressMeter - Starting traversal
19:23:42.245 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:42.291 INFO ProgressMeter - chr1:6212018 0.0 2791 3640434.8
19:23:42.291 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
19:23:42.291 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
19:23:42.291 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
19:23:42.292 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
19:23:42.292 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
19:23:42.292 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
19:23:42.293 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
19:23:42.293 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:42.324 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:42.341 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
19:23:42.358 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
19:23:42.375 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
19:23:42.392 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
19:23:42.409 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
19:23:42.426 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
19:23:42.443 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
19:23:42.465 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
19:23:42.481 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
19:23:42.497 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
19:23:42.514 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
19:23:42.530 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
19:23:42.530 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
19:23:42.531 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
19:23:42.540 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
19:23:42.540 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:42.540 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:42.540 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
19:23:42.540 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
19:23:42.548 INFO TrancheManager - Finding 4 tranches for 2786 variants
19:23:42.549 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
19:23:42.549 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
19:23:42.549 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]
19:23:42.549 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
19:23:42.549 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
19:23:42.549 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]
19:23:42.549 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
19:23:42.550 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
19:23:42.550 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]
19:23:42.550 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
19:23:42.550 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
19:23:42.550 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]
19:23:42.550 INFO VariantRecalibrator - Writing out recalibration table...
19:23:42.565 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:42 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
19:23:42.568 INFO gatk - Initializing VQSR tests/resetting random number generator
19:23:42.588 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:42.588 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:42.588 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:42.588 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:42.588 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:42.588 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:42 PM GMT
19:23:42.588 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:42.588 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:42.589 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:42.589 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:42.589 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:42.589 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:42.589 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:42.589 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:42.589 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:42.589 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:42.589 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:42.589 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:42.589 INFO VariantRecalibrator - Requester pays: disabled
19:23:42.589 INFO VariantRecalibrator - Initializing engine
19:23:42.590 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
19:23:42.592 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
19:23:42.594 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
19:23:42.596 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
19:23:42.598 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
19:23:42.599 INFO VariantRecalibrator - Done initializing engine
19:23:42.599 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
19:23:42.599 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
19:23:42.599 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
19:23:42.600 INFO ProgressMeter - Starting traversal
19:23:42.600 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:43.537 INFO ProgressMeter - 20:9944766 0.0 131821 8441045.9
19:23:43.538 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
19:23:43.540 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
19:23:43.543 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
19:23:43.545 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
19:23:43.567 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
19:23:43.569 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
19:23:43.569 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:43.824 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:43.933 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
19:23:44.043 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
19:23:44.155 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
19:23:44.268 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
19:23:44.392 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
19:23:44.485 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
19:23:44.579 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
19:23:44.673 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
19:23:44.766 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
19:23:44.860 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
19:23:44.935 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
19:23:44.942 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
19:23:45.009 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
19:23:45.009 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:45.010 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:45.011 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
19:23:45.013 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
19:23:45.192 INFO TrancheManager - Finding 12 tranches for 131821 variants
19:23:45.224 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
19:23:45.228 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
19:23:45.228 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]
19:23:45.228 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
19:23:45.233 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001
19:23:45.233 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]
19:23:45.233 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
19:23:45.237 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
19:23:45.237 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]
19:23:45.237 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
19:23:45.241 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002
19:23:45.241 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]
19:23:45.241 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
19:23:45.245 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004
19:23:45.245 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]
19:23:45.246 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
19:23:45.250 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005
19:23:45.250 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]
19:23:45.250 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
19:23:45.254 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006
19:23:45.254 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]
19:23:45.254 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
19:23:45.258 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007
19:23:45.258 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]
19:23:45.258 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
19:23:45.262 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
19:23:45.262 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]
19:23:45.262 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
19:23:45.266 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020
19:23:45.266 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]
19:23:45.266 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
19:23:45.270 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030
19:23:45.270 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]
19:23:45.270 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
19:23:45.274 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
19:23:45.274 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]
19:23:45.274 INFO VariantRecalibrator - Writing out recalibration table...
19:23:45.561 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:45 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
19:23:45.583 INFO gatk - Initializing VQSR tests/resetting random number generator
19:23:45.609 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:45.609 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:45.609 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:45.609 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:45.609 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:45.609 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:45 PM GMT
19:23:45.609 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:45.609 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:45.609 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:45.609 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:45.609 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:45.610 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:45.610 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:45.610 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:45.610 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:45.610 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:45.610 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:45.610 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:45.610 INFO VariantRecalibrator - Requester pays: disabled
19:23:45.610 INFO VariantRecalibrator - Initializing engine
19:23:45.611 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
19:23:45.622 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
19:23:45.657 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
19:23:45.672 INFO VariantRecalibrator - Done initializing engine
19:23:45.672 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
19:23:45.682 INFO ProgressMeter - Starting traversal
19:23:45.682 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:45.725 INFO ProgressMeter - chr1:6212018 0.0 2791 3894418.6
19:23:45.725 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
19:23:45.725 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
19:23:45.725 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
19:23:45.726 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
19:23:45.726 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
19:23:45.726 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
19:23:45.726 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
19:23:45.726 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:45.757 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:45.775 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
19:23:45.792 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
19:23:45.809 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
19:23:45.826 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
19:23:45.843 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
19:23:45.860 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
19:23:45.877 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
19:23:45.895 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
19:23:45.913 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
19:23:45.930 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
19:23:45.947 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
19:23:45.964 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
19:23:45.964 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
19:23:45.965 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
19:23:45.974 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
19:23:45.974 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:45.974 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:45.974 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
19:23:45.974 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
19:23:45.982 INFO TrancheManager - Finding 12 tranches for 2786 variants
19:23:45.983 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
19:23:45.983 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
19:23:45.983 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]
19:23:45.983 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
19:23:45.983 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001
19:23:45.983 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]
19:23:45.983 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
19:23:45.983 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
19:23:45.984 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]
19:23:45.985 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
19:23:45.985 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002
19:23:45.985 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]
19:23:45.985 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
19:23:45.985 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004
19:23:45.985 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]
19:23:45.985 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
19:23:45.986 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005
19:23:45.986 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]
19:23:45.986 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
19:23:45.986 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006
19:23:45.986 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]
19:23:45.986 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
19:23:45.986 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007
19:23:45.986 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]
19:23:45.987 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
19:23:45.987 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
19:23:45.987 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]
19:23:45.987 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
19:23:45.987 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020
19:23:45.987 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]
19:23:45.987 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
19:23:45.987 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030
19:23:45.988 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]
19:23:45.988 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
19:23:45.988 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
19:23:45.988 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]
19:23:45.988 INFO VariantRecalibrator - Writing out recalibration table...
19:23:46.001 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:46 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
19:23:46.004 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 7:23:48 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
19:23:48.423 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:48.423 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:48.423 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:48.423 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:48.424 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:48.424 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:48 PM GMT
19:23:48.424 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:48.424 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:48.424 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:48.424 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:48.424 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:48.424 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:48.424 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:48.424 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:48.424 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:48.424 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:48.424 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:48.424 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:48.424 INFO VariantRecalibrator - Requester pays: disabled
19:23:48.424 INFO VariantRecalibrator - Initializing engine
19:23:48.425 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
19:23:48.428 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
19:23:48.430 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
19:23:48.431 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
19:23:48.434 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/g94982_20_1m_10m_python_2dcnn.indels.vcf.gz
19:23:48.446 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
19:23:48.447 INFO VariantRecalibrator - Done initializing engine
19:23:48.448 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
19:23:48.448 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
19:23:48.448 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
19:23:48.450 INFO ProgressMeter - Starting traversal
19:23:48.450 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:49.437 INFO ProgressMeter - 20:9938789 0.0 134919 8201762.9
19:23:49.438 INFO ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
19:23:49.440 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
19:23:49.444 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
19:23:49.448 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
19:23:49.479 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
19:23:49.481 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
19:23:49.481 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:49.682 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:49.765 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.13181
19:23:49.849 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.46782
19:23:49.934 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 9.04961
19:23:50.022 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.04477
19:23:50.109 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01711
19:23:50.197 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.02053
19:23:50.284 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.01194
19:23:50.372 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01038
19:23:50.459 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.06192
19:23:50.556 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01281
19:23:50.630 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00457
19:23:50.660 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
19:23:50.665 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
19:23:50.753 INFO VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
19:23:50.754 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:50.756 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:50.757 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.05287
19:23:50.758 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.02030
19:23:50.759 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.00986
19:23:50.761 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.00749
19:23:50.762 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.00850
19:23:50.763 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01430
19:23:50.764 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02541
19:23:50.765 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.02173
19:23:50.766 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01024
19:23:50.767 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00479
19:23:50.769 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00245
19:23:50.769 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
19:23:50.770 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
19:23:50.938 INFO TrancheManager - Finding 4 tranches for 134603 variants
19:23:50.971 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
19:23:50.975 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
19:23:50.975 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]
19:23:50.975 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
19:23:50.979 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001
19:23:50.979 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]
19:23:50.979 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
19:23:50.983 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010
19:23:50.983 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]
19:23:50.983 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
19:23:50.987 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100
19:23:50.987 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]
19:23:50.987 INFO VariantRecalibrator - Writing out recalibration table...
19:23:51.270 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:51 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
19:23:51.272 INFO gatk - Initializing VQSR tests/resetting random number generator
19:23:51.289 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:51.289 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-5-g0192957-SNAPSHOT
19:23:51.289 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
19:23:51.289 INFO VariantRecalibrator - Executing as root@39b899212c20 on Linux v6.11.0-1014-azure amd64
19:23:51.289 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
19:23:51.289 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 7:23:51 PM GMT
19:23:51.289 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:51.289 INFO VariantRecalibrator - ------------------------------------------------------------
19:23:51.289 INFO VariantRecalibrator - HTSJDK Version: 4.2.0-7-gb6a1842-SNAPSHOT
19:23:51.289 INFO VariantRecalibrator - Picard Version: 3.4.0
19:23:51.289 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
19:23:51.289 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:23:51.290 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:23:51.290 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:23:51.290 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:23:51.290 INFO VariantRecalibrator - Deflater: IntelDeflater
19:23:51.290 INFO VariantRecalibrator - Inflater: IntelInflater
19:23:51.290 INFO VariantRecalibrator - GCS max retries/reopens: 20
19:23:51.290 INFO VariantRecalibrator - Requester pays: disabled
19:23:51.290 INFO VariantRecalibrator - Initializing engine
19:23:51.291 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
19:23:51.292 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
19:23:51.294 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
19:23:51.295 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
19:23:51.297 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
19:23:51.298 INFO VariantRecalibrator - Done initializing engine
19:23:51.298 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
19:23:51.298 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
19:23:51.298 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
19:23:51.298 INFO ProgressMeter - Starting traversal
19:23:51.299 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
19:23:52.257 INFO ProgressMeter - 20:9944766 0.0 131821 8256012.5
19:23:52.257 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
19:23:52.259 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
19:23:52.261 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
19:23:52.263 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
19:23:52.283 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
19:23:52.284 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
19:23:52.284 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:52.542 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:52.654 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
19:23:52.767 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
19:23:52.881 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
19:23:53.001 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
19:23:53.117 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
19:23:53.232 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
19:23:53.350 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
19:23:53.475 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
19:23:53.569 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
19:23:53.663 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
19:23:53.739 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
19:23:53.746 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
19:23:53.812 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
19:23:53.812 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
19:23:53.814 INFO VariantRecalibratorEngine - Finished iteration 0.
19:23:53.814 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
19:23:53.816 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
19:23:53.994 INFO TrancheManager - Finding 12 tranches for 131821 variants
19:23:54.026 INFO TrancheManager - VQSLODTranche threshold 10.00 => selection metric threshold 0.900
19:23:54.034 INFO TrancheManager - Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262
19:23:54.034 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
19:23:54.034 INFO TrancheManager - VQSLODTranche threshold 8.00 => selection metric threshold 0.920
19:23:54.040 INFO TrancheManager - Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114
19:23:54.040 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
19:23:54.040 INFO TrancheManager - VQSLODTranche threshold 6.00 => selection metric threshold 0.940
19:23:54.044 INFO TrancheManager - Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052
19:23:54.044 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
19:23:54.044 INFO TrancheManager - VQSLODTranche threshold 4.00 => selection metric threshold 0.960
19:23:54.049 INFO TrancheManager - Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023
19:23:54.049 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
19:23:54.049 INFO TrancheManager - VQSLODTranche threshold 2.00 => selection metric threshold 0.980
19:23:54.053 INFO TrancheManager - Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009
19:23:54.053 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
19:23:54.053 INFO TrancheManager - VQSLODTranche threshold 0.00 => selection metric threshold 1.000
19:23:54.058 INFO TrancheManager - Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004
19:23:54.058 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
19:23:54.058 INFO TrancheManager - VQSLODTranche threshold -2.00 => selection metric threshold 1.020
19:23:54.063 INFO TrancheManager - Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001
19:23:54.064 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
19:23:54.064 INFO TrancheManager - VQSLODTranche threshold -4.00 => selection metric threshold 1.040
19:23:54.070 INFO TrancheManager - Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001
19:23:54.070 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
19:23:54.070 INFO TrancheManager - VQSLODTranche threshold -6.00 => selection metric threshold 1.060
19:23:54.075 INFO TrancheManager - Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001
19:23:54.075 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
19:23:54.075 INFO TrancheManager - VQSLODTranche threshold -8.00 => selection metric threshold 1.080
19:23:54.079 INFO TrancheManager - Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000
19:23:54.079 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
19:23:54.079 INFO TrancheManager - VQSLODTranche threshold -10.00 => selection metric threshold 1.100
19:23:54.083 INFO TrancheManager - Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000
19:23:54.083 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
19:23:54.083 INFO TrancheManager - VQSLODTranche threshold -12.00 => selection metric threshold 1.120
19:23:54.088 INFO TrancheManager - Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000
19:23:54.088 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
19:23:54.088 INFO VariantRecalibrator - Writing out recalibration table...
19:23:54.363 INFO VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
19:23:54.367 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 7:23:54 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 7:24:53 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000