[May 27, 2025 at 1:58:54 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.08 minutes.
Runtime.totalMemory()=1218445312
13:58:54.712 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:54.712 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:58:54.712 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:58:54.713 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:58:54.713 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:58:54.713 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:58:54 PM UTC
13:58:54.713 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:54.713 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:54.714 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:58:54.714 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:58:54.714 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:58:54.714 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:58:54.714 INFO VariantRecalibrator - Deflater: IntelDeflater
13:58:54.714 INFO VariantRecalibrator - Inflater: IntelInflater
13:58:54.714 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:58:54.714 INFO VariantRecalibrator - Requester pays: disabled
13:58:54.714 INFO VariantRecalibrator - Initializing engine
13:58:54.717 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
13:58:54.745 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
13:58:54.835 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
13:58:54.869 INFO VariantRecalibrator - Done initializing engine
13:58:54.869 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
13:58:54.909 INFO ProgressMeter - Starting traversal
13:58:54.909 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:58:55.034 INFO ProgressMeter - chr1:6212018 0.0 2791 1339680.0
13:58:55.035 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
13:58:55.035 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
13:58:55.036 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
13:58:55.036 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
13:58:55.037 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
13:58:55.045 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
13:58:55.045 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
13:58:55.045 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:58:55.102 INFO VariantRecalibratorEngine - Finished iteration 0.
13:58:55.130 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.16919
13:58:55.159 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.14268
13:58:55.187 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.19617
13:58:55.205 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.09047
13:58:55.221 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.05235
13:58:55.238 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04028
13:58:55.254 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02103
13:58:55.271 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01461
13:58:55.287 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01136
13:58:55.304 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00583
13:58:55.320 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00291
13:58:55.330 INFO VariantRecalibratorEngine - Convergence after 58 iterations!
13:58:55.335 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
13:58:55.351 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
13:58:55.360 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:58:55 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1218445312
13:58:55.365 INFO gatk - Initializing VQSR tests/resetting random number generator
13:58:55.385 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:55.385 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:58:55.385 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:58:55.385 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:58:55.385 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:58:55.385 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:58:55 PM UTC
13:58:55.385 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:55.385 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:55.385 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:58:55.386 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:58:55.386 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:58:55.386 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:58:55.386 INFO VariantRecalibrator - Deflater: IntelDeflater
13:58:55.386 INFO VariantRecalibrator - Inflater: IntelInflater
13:58:55.386 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:58:55.386 INFO VariantRecalibrator - Requester pays: disabled
13:58:55.386 INFO VariantRecalibrator - Initializing engine
13:58:55.388 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
13:58:55.391 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
13:58:55.394 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
13:58:55.397 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
13:58:55.402 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
13:58:55.403 INFO VariantRecalibrator - Done initializing engine
13:58:55.405 WARN VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
13:58:55.405 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
13:58:55.406 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
13:58:55.406 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
13:58:55.409 INFO ProgressMeter - Starting traversal
13:58:55.409 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:58:56.524 INFO ProgressMeter - 20:9944766 0.0 131821 7093506.7
13:58:56.524 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
13:58:56.529 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
13:58:56.534 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
13:58:56.538 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
13:58:56.561 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
13:58:56.564 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
13:58:56.564 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:58:56.824 INFO VariantRecalibratorEngine - Finished iteration 0.
13:58:56.926 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
13:58:57.031 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
13:58:57.137 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
13:58:57.246 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
13:58:57.354 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
13:58:57.461 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
13:58:57.578 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
13:58:57.669 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
13:58:57.760 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
13:58:57.851 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
13:58:57.924 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
13:58:57.931 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
13:58:58.004 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
13:58:58.004 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:58:58.006 INFO VariantRecalibratorEngine - Finished iteration 0.
13:58:58.006 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
13:58:58.008 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
13:58:58.197 INFO TrancheManager - Finding 4 tranches for 131821 variants
13:58:58.232 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
13:58:58.237 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
13:58:58.238 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]
13:58:58.238 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
13:58:58.242 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
13:58:58.242 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]
13:58:58.243 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
13:58:58.247 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
13:58:58.247 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]
13:58:58.247 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
13:58:58.252 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
13:58:58.252 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]
13:58:58.252 INFO VariantRecalibrator - Writing out recalibration table...
13:58:58.796 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:58:58 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1218445312
13:58:58.841 INFO gatk - Initializing VQSR tests/resetting random number generator
13:58:58.857 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:58.857 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:58:58.857 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:58:58.857 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:58:58.857 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:58:58.858 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:58:58 PM UTC
13:58:58.858 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:58.858 INFO VariantRecalibrator - ------------------------------------------------------------
13:58:58.858 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:58:58.858 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:58:58.858 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:58:58.858 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:58:58.858 INFO VariantRecalibrator - Deflater: IntelDeflater
13:58:58.858 INFO VariantRecalibrator - Inflater: IntelInflater
13:58:58.858 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:58:58.858 INFO VariantRecalibrator - Requester pays: disabled
13:58:58.859 INFO VariantRecalibrator - Initializing engine
13:58:58.860 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
13:58:58.864 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
13:58:58.866 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
13:58:58.874 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
13:58:58.879 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
13:58:58.880 INFO VariantRecalibrator - Done initializing engine
13:58:58.880 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
13:58:58.881 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
13:58:58.881 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
13:58:58.883 INFO ProgressMeter - Starting traversal
13:58:58.883 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:58:59.847 INFO ProgressMeter - 20:9944766 0.0 131821 8204626.6
13:58:59.847 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
13:58:59.850 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
13:58:59.854 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
13:58:59.857 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
13:58:59.880 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
13:58:59.882 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
13:58:59.882 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:00.135 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:00.237 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
13:59:00.351 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
13:59:00.437 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
13:59:00.525 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
13:59:00.613 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
13:59:00.699 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
13:59:00.787 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
13:59:00.875 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
13:59:00.964 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
13:59:01.052 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
13:59:01.124 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
13:59:01.130 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
13:59:01.203 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
13:59:01.204 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:01.205 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:01.205 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
13:59:01.207 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
13:59:01.406 INFO TrancheManager - Finding 4 tranches for 131821 variants
13:59:01.440 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
13:59:01.446 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
13:59:01.446 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]
13:59:01.446 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
13:59:01.452 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
13:59:01.452 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]
13:59:01.452 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
13:59:01.458 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
13:59:01.458 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]
13:59:01.459 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
13:59:01.467 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
13:59:01.467 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]
13:59:01.467 INFO VariantRecalibrator - Writing out recalibration table...
13:59:01.779 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:59:01 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1218445312
13:59:01.804 INFO gatk - Initializing VQSR tests/resetting random number generator
13:59:01.815 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:01.815 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:59:01.815 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:59:01.816 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:59:01.816 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:59:01.816 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:59:01 PM UTC
13:59:01.816 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:01.816 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:01.816 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:59:01.816 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:59:01.816 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:59:01.816 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:59:01.816 INFO VariantRecalibrator - Deflater: IntelDeflater
13:59:01.816 INFO VariantRecalibrator - Inflater: IntelInflater
13:59:01.817 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:59:01.817 INFO VariantRecalibrator - Requester pays: disabled
13:59:01.817 INFO VariantRecalibrator - Initializing engine
13:59:01.818 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
13:59:01.837 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
13:59:01.890 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
13:59:01.916 INFO VariantRecalibrator - Done initializing engine
13:59:01.917 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
13:59:01.933 INFO ProgressMeter - Starting traversal
13:59:01.933 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:59:01.991 INFO ProgressMeter - chr1:6212018 0.0 2791 2887241.4
13:59:01.992 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
13:59:01.992 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
13:59:01.992 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
13:59:01.992 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
13:59:01.993 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
13:59:01.994 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
13:59:01.994 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
13:59:01.994 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:02.025 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:02.041 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
13:59:02.058 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
13:59:02.075 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
13:59:02.092 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
13:59:02.109 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
13:59:02.125 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
13:59:02.142 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
13:59:02.158 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
13:59:02.175 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
13:59:02.192 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
13:59:02.208 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
13:59:02.225 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
13:59:02.225 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
13:59:02.227 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
13:59:02.242 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
13:59:02.242 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:02.242 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:02.242 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
13:59:02.242 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
13:59:02.253 INFO TrancheManager - Finding 4 tranches for 2786 variants
13:59:02.255 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
13:59:02.255 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
13:59:02.255 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]
13:59:02.255 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
13:59:02.256 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
13:59:02.256 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]
13:59:02.256 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
13:59:02.256 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
13:59:02.256 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]
13:59:02.256 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
13:59:02.256 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
13:59:02.257 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]
13:59:02.257 INFO VariantRecalibrator - Writing out recalibration table...
13:59:02.287 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:59:02 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1218445312
13:59:02.292 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 1:59:04 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1218445312
13:59:04.829 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:04.829 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:59:04.829 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:59:04.829 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:59:04.829 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:59:04.830 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:59:04 PM UTC
13:59:04.830 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:04.830 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:04.830 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:59:04.830 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:59:04.830 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:59:04.830 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:59:04.830 INFO VariantRecalibrator - Deflater: IntelDeflater
13:59:04.830 INFO VariantRecalibrator - Inflater: IntelInflater
13:59:04.830 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:59:04.830 INFO VariantRecalibrator - Requester pays: disabled
13:59:04.830 INFO VariantRecalibrator - Initializing engine
13:59:04.831 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
13:59:04.833 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
13:59:04.835 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
13:59:04.836 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
13:59:04.838 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/g94982_20_1m_10m_python_2dcnn.indels.vcf.gz
13:59:04.858 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
13:59:04.859 INFO VariantRecalibrator - Done initializing engine
13:59:04.859 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
13:59:04.860 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
13:59:04.860 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
13:59:04.863 INFO ProgressMeter - Starting traversal
13:59:04.863 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:59:05.905 INFO ProgressMeter - 20:9938789 0.0 134919 7768848.4
13:59:05.905 INFO ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
13:59:05.908 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
13:59:05.913 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
13:59:05.916 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
13:59:05.938 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
13:59:05.940 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
13:59:05.940 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:06.141 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:06.219 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.13181
13:59:06.299 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.46782
13:59:06.380 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 9.04961
13:59:06.462 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.04477
13:59:06.544 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01711
13:59:06.628 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.02053
13:59:06.715 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.01194
13:59:06.782 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01038
13:59:06.849 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.06192
13:59:06.916 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01281
13:59:06.986 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00457
13:59:07.013 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
13:59:07.019 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
13:59:07.129 INFO VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
13:59:07.129 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:07.132 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:07.133 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.05287
13:59:07.134 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.02030
13:59:07.135 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.00986
13:59:07.137 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.00749
13:59:07.138 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.00850
13:59:07.139 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01430
13:59:07.140 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02541
13:59:07.141 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.02173
13:59:07.143 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01024
13:59:07.144 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00479
13:59:07.145 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00245
13:59:07.146 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
13:59:07.147 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
13:59:07.346 INFO TrancheManager - Finding 4 tranches for 134603 variants
13:59:07.389 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
13:59:07.394 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
13:59:07.394 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]
13:59:07.394 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
13:59:07.399 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001
13:59:07.399 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]
13:59:07.399 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
13:59:07.403 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010
13:59:07.403 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]
13:59:07.404 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
13:59:07.408 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100
13:59:07.408 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]
13:59:07.408 INFO VariantRecalibrator - Writing out recalibration table...
13:59:07.718 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:59:07 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1218445312
13:59:07.720 INFO gatk - Initializing VQSR tests/resetting random number generator
13:59:07.728 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:07.728 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:59:07.728 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:59:07.728 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:59:07.728 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:59:07.728 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:59:07 PM UTC
13:59:07.728 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:07.728 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:07.728 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:59:07.729 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:59:07.729 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:59:07.729 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:59:07.729 INFO VariantRecalibrator - Deflater: IntelDeflater
13:59:07.729 INFO VariantRecalibrator - Inflater: IntelInflater
13:59:07.729 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:59:07.729 INFO VariantRecalibrator - Requester pays: disabled
13:59:07.729 INFO VariantRecalibrator - Initializing engine
13:59:07.730 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
13:59:07.732 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
13:59:07.733 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
13:59:07.734 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
13:59:07.736 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
13:59:07.737 INFO VariantRecalibrator - Done initializing engine
13:59:07.737 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
13:59:07.738 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
13:59:07.738 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
13:59:07.739 INFO ProgressMeter - Starting traversal
13:59:07.739 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:59:08.675 INFO ProgressMeter - 20:9944766 0.0 131821 8459101.6
13:59:08.675 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
13:59:08.677 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
13:59:08.681 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
13:59:08.683 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
13:59:08.708 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
13:59:08.709 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
13:59:08.710 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:08.966 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:09.067 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
13:59:09.172 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
13:59:09.290 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
13:59:09.377 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
13:59:09.465 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
13:59:09.551 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
13:59:09.639 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
13:59:09.727 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
13:59:09.815 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
13:59:09.903 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
13:59:09.975 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
13:59:09.981 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
13:59:10.054 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
13:59:10.054 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:10.057 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:10.058 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
13:59:10.059 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
13:59:10.244 INFO TrancheManager - Finding 12 tranches for 131821 variants
13:59:10.289 INFO TrancheManager - VQSLODTranche threshold 10.00 => selection metric threshold 0.900
13:59:10.303 INFO TrancheManager - Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262
13:59:10.303 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
13:59:10.303 INFO TrancheManager - VQSLODTranche threshold 8.00 => selection metric threshold 0.920
13:59:10.312 INFO TrancheManager - Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114
13:59:10.313 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
13:59:10.313 INFO TrancheManager - VQSLODTranche threshold 6.00 => selection metric threshold 0.940
13:59:10.320 INFO TrancheManager - Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052
13:59:10.320 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
13:59:10.320 INFO TrancheManager - VQSLODTranche threshold 4.00 => selection metric threshold 0.960
13:59:10.327 INFO TrancheManager - Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023
13:59:10.327 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
13:59:10.327 INFO TrancheManager - VQSLODTranche threshold 2.00 => selection metric threshold 0.980
13:59:10.333 INFO TrancheManager - Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009
13:59:10.333 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
13:59:10.334 INFO TrancheManager - VQSLODTranche threshold 0.00 => selection metric threshold 1.000
13:59:10.338 INFO TrancheManager - Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004
13:59:10.338 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
13:59:10.338 INFO TrancheManager - VQSLODTranche threshold -2.00 => selection metric threshold 1.020
13:59:10.342 INFO TrancheManager - Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001
13:59:10.342 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
13:59:10.342 INFO TrancheManager - VQSLODTranche threshold -4.00 => selection metric threshold 1.040
13:59:10.347 INFO TrancheManager - Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001
13:59:10.347 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
13:59:10.347 INFO TrancheManager - VQSLODTranche threshold -6.00 => selection metric threshold 1.060
13:59:10.353 INFO TrancheManager - Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001
13:59:10.353 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
13:59:10.353 INFO TrancheManager - VQSLODTranche threshold -8.00 => selection metric threshold 1.080
13:59:10.357 INFO TrancheManager - Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000
13:59:10.357 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
13:59:10.357 INFO TrancheManager - VQSLODTranche threshold -10.00 => selection metric threshold 1.100
13:59:10.362 INFO TrancheManager - Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000
13:59:10.362 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
13:59:10.362 INFO TrancheManager - VQSLODTranche threshold -12.00 => selection metric threshold 1.120
13:59:10.366 INFO TrancheManager - Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000
13:59:10.366 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
13:59:10.366 INFO VariantRecalibrator - Writing out recalibration table...
13:59:10.678 INFO VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
13:59:10.684 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:59:10 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1218445312
13:59:10.707 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 1:59:12 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1218445312
13:59:12.158 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:12.158 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:59:12.158 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:59:12.158 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:59:12.158 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:59:12.158 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:59:12 PM UTC
13:59:12.158 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:12.158 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:12.158 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:59:12.158 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:59:12.158 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:59:12.158 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:59:12.158 INFO VariantRecalibrator - Deflater: IntelDeflater
13:59:12.158 INFO VariantRecalibrator - Inflater: IntelInflater
13:59:12.159 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:59:12.159 INFO VariantRecalibrator - Requester pays: disabled
13:59:12.159 INFO VariantRecalibrator - Initializing engine
13:59:12.160 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
13:59:12.170 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
13:59:12.206 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
13:59:12.220 INFO VariantRecalibrator - Done initializing engine
13:59:12.220 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
13:59:12.232 INFO ProgressMeter - Starting traversal
13:59:12.232 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:59:12.282 INFO ProgressMeter - chr1:6212018 0.0 2791 3349200.0
13:59:12.282 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
13:59:12.283 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
13:59:12.283 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
13:59:12.283 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
13:59:12.283 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
13:59:12.283 INFO VariantDataManager - AS_FS: mean = 1.08 standard deviation = 2.43
13:59:12.284 INFO VariantDataManager - AS_MQRankSum: mean = 0.00 standard deviation = 0.01
13:59:12.285 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
13:59:12.285 INFO VariantDataManager - Training with 2769 variants after standard deviation thresholding.
13:59:12.285 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:12.321 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:12.345 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.56007
13:59:12.378 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.67355
13:59:12.402 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 5.08559
13:59:12.434 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.01567
13:59:12.458 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.02021
13:59:12.482 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01989
13:59:12.505 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02504
13:59:12.529 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03657
13:59:12.553 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.04057
13:59:12.576 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.08648
13:59:12.600 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.01514
13:59:12.624 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00496
13:59:12.647 INFO VariantRecalibratorEngine - Finished iteration 65. Current change in mixture coefficients = 0.00163
13:59:12.647 INFO VariantRecalibratorEngine - Convergence after 65 iterations!
13:59:12.650 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
13:59:12.669 INFO VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
13:59:12.669 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:12.669 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:12.669 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
13:59:12.669 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
13:59:12.683 INFO TrancheManager - Finding 4 tranches for 2786 variants
13:59:12.684 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
13:59:12.684 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
13:59:12.684 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]
13:59:12.684 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
13:59:12.684 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
13:59:12.684 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]
13:59:12.685 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
13:59:12.685 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
13:59:12.685 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]
13:59:12.685 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
13:59:12.685 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
13:59:12.685 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]
13:59:12.685 INFO VariantRecalibrator - Writing out recalibration table...
13:59:12.700 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:59:12 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1218445312
13:59:12.701 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 27, 2025 at 1:59:15 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1218445312
[May 27, 2025 at 1:59:15 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1218445312
[May 27, 2025 at 1:59:15 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1218445312
[May 27, 2025 at 1:59:15 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1218445312
[May 27, 2025 at 1:59:16 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1218445312
[May 27, 2025 at 1:59:17 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1218445312
13:59:17.800 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:17.801 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:59:17.801 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:59:17.801 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:59:17.801 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:59:17.801 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:59:17 PM UTC
13:59:17.801 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:17.801 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:17.801 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:59:17.801 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:59:17.801 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:59:17.801 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:59:17.801 INFO VariantRecalibrator - Deflater: IntelDeflater
13:59:17.801 INFO VariantRecalibrator - Inflater: IntelInflater
13:59:17.802 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:59:17.802 INFO VariantRecalibrator - Requester pays: disabled
13:59:17.802 INFO VariantRecalibrator - Initializing engine
13:59:17.803 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
13:59:17.805 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
13:59:17.806 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
13:59:17.808 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
13:59:17.811 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
13:59:17.812 INFO VariantRecalibrator - Done initializing engine
13:59:17.812 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
13:59:17.812 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
13:59:17.812 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
13:59:17.813 INFO ProgressMeter - Starting traversal
13:59:17.813 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:59:18.794 INFO ProgressMeter - 20:9944766 0.0 131821 8062446.5
13:59:18.794 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
13:59:18.797 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
13:59:18.800 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
13:59:18.803 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
13:59:18.829 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
13:59:18.830 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
13:59:18.831 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:19.086 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:19.200 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
13:59:19.283 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
13:59:19.367 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
13:59:19.453 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
13:59:19.540 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
13:59:19.626 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
13:59:19.715 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
13:59:19.803 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
13:59:19.891 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
13:59:19.980 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
13:59:20.051 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
13:59:20.058 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
13:59:20.126 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
13:59:20.126 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:20.127 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:20.128 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
13:59:20.130 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
13:59:20.318 INFO TrancheManager - Finding 12 tranches for 131821 variants
13:59:20.350 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
13:59:20.355 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
13:59:20.355 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]
13:59:20.355 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
13:59:20.359 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001
13:59:20.359 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]
13:59:20.359 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
13:59:20.363 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
13:59:20.364 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]
13:59:20.364 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
13:59:20.368 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002
13:59:20.368 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]
13:59:20.368 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
13:59:20.372 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004
13:59:20.372 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]
13:59:20.372 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
13:59:20.377 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005
13:59:20.377 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]
13:59:20.377 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
13:59:20.381 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006
13:59:20.381 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]
13:59:20.381 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
13:59:20.385 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007
13:59:20.386 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]
13:59:20.386 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
13:59:20.390 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
13:59:20.390 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]
13:59:20.390 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
13:59:20.394 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020
13:59:20.395 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]
13:59:20.395 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
13:59:20.400 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030
13:59:20.400 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]
13:59:20.400 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
13:59:20.404 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
13:59:20.404 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]
13:59:20.405 INFO VariantRecalibrator - Writing out recalibration table...
13:59:20.702 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:59:20 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1218445312
13:59:20.727 INFO gatk - Initializing VQSR tests/resetting random number generator
13:59:20.734 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:20.735 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
13:59:20.735 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
13:59:20.735 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
13:59:20.735 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
13:59:20.735 INFO VariantRecalibrator - Start Date/Time: May 27, 2025 at 1:59:20 PM UTC
13:59:20.735 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:20.735 INFO VariantRecalibrator - ------------------------------------------------------------
13:59:20.735 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
13:59:20.735 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
13:59:20.735 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
13:59:20.735 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
13:59:20.735 INFO VariantRecalibrator - Deflater: IntelDeflater
13:59:20.735 INFO VariantRecalibrator - Inflater: IntelInflater
13:59:20.735 INFO VariantRecalibrator - GCS max retries/reopens: 20
13:59:20.735 INFO VariantRecalibrator - Requester pays: disabled
13:59:20.735 INFO VariantRecalibrator - Initializing engine
13:59:20.736 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
13:59:20.745 INFO FeatureManager - Using codec VCFCodec to read file file:///home/runner/work/gatk/gatk/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
13:59:20.778 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
13:59:20.789 INFO VariantRecalibrator - Done initializing engine
13:59:20.790 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
13:59:20.799 INFO ProgressMeter - Starting traversal
13:59:20.799 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
13:59:20.844 INFO ProgressMeter - chr1:6212018 0.0 2791 3721333.3
13:59:20.844 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
13:59:20.845 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
13:59:20.845 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
13:59:20.845 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
13:59:20.845 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
13:59:20.846 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
13:59:20.846 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
13:59:20.846 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:20.876 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:20.893 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
13:59:20.909 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
13:59:20.926 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
13:59:20.942 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
13:59:20.959 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
13:59:20.975 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
13:59:20.992 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
13:59:21.008 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
13:59:21.028 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
13:59:21.045 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
13:59:21.061 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
13:59:21.077 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
13:59:21.077 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
13:59:21.079 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
13:59:21.088 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
13:59:21.088 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
13:59:21.088 INFO VariantRecalibratorEngine - Finished iteration 0.
13:59:21.088 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
13:59:21.088 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
13:59:21.096 INFO TrancheManager - Finding 12 tranches for 2786 variants
13:59:21.096 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
13:59:21.096 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
13:59:21.097 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]
13:59:21.097 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
13:59:21.097 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001
13:59:21.097 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]
13:59:21.097 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
13:59:21.097 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
13:59:21.097 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]
13:59:21.097 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
13:59:21.097 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002
13:59:21.097 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]
13:59:21.097 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
13:59:21.097 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004
13:59:21.097 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]
13:59:21.097 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
13:59:21.098 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005
13:59:21.098 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]
13:59:21.098 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
13:59:21.098 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006
13:59:21.098 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]
13:59:21.098 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
13:59:21.098 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007
13:59:21.098 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]
13:59:21.098 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
13:59:21.098 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
13:59:21.098 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]
13:59:21.098 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
13:59:21.098 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020
13:59:21.098 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]
13:59:21.098 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
13:59:21.098 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030
13:59:21.098 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]
13:59:21.098 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
13:59:21.099 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
13:59:21.099 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]
13:59:21.099 INFO VariantRecalibrator - Writing out recalibration table...
13:59:21.112 INFO VariantRecalibrator - Shutting down engine
[May 27, 2025 at 1:59:21 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1218445312
[May 27, 2025 at 2:00:31 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1220542464