[May 19, 2025 at 3:53:53 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=629145600
15:53:53.264 INFO VariantRecalibrator - ------------------------------------------------------------
15:53:53.265 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:53:53.265 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:53:53.265 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:53:53.265 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:53:53.265 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:53:53 PM UTC
15:53:53.265 INFO VariantRecalibrator - ------------------------------------------------------------
15:53:53.265 INFO VariantRecalibrator - ------------------------------------------------------------
15:53:53.266 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:53:53.266 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:53:53.266 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:53:53.266 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:53:53.266 INFO VariantRecalibrator - Deflater: IntelDeflater
15:53:53.266 INFO VariantRecalibrator - Inflater: IntelInflater
15:53:53.266 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:53:53.266 INFO VariantRecalibrator - Requester pays: disabled
15:53:53.266 INFO VariantRecalibrator - Initializing engine
15:53:53.270 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
15:53:53.303 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
15:53:53.398 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
15:53:53.434 INFO VariantRecalibrator - Done initializing engine
15:53:53.434 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
15:53:53.472 INFO ProgressMeter - Starting traversal
15:53:53.473 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:53:53.610 INFO ProgressMeter - chr1:6212018 0.0 2791 1222335.8
15:53:53.611 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
15:53:53.612 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
15:53:53.613 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
15:53:53.614 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
15:53:53.615 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
15:53:53.616 INFO VariantDataManager - AS_FS: mean = 1.08 standard deviation = 2.43
15:53:53.617 INFO VariantDataManager - AS_MQRankSum: mean = 0.00 standard deviation = 0.01
15:53:53.629 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
15:53:53.629 INFO VariantDataManager - Training with 2769 variants after standard deviation thresholding.
15:53:53.630 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:53:53.687 INFO VariantRecalibratorEngine - Finished iteration 0.
15:53:53.730 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.56007
15:53:53.774 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.67355
15:53:53.818 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 5.08559
15:53:53.863 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.01567
15:53:53.913 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.02021
15:53:53.938 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01989
15:53:53.965 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02504
15:53:53.998 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03657
15:53:54.023 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.04057
15:53:54.049 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.08648
15:53:54.073 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.01514
15:53:54.098 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00496
15:53:54.128 INFO VariantRecalibratorEngine - Finished iteration 65. Current change in mixture coefficients = 0.00163
15:53:54.128 INFO VariantRecalibratorEngine - Convergence after 65 iterations!
15:53:54.133 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:53:54.171 INFO VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
15:53:54.171 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:53:54.172 INFO VariantRecalibratorEngine - Finished iteration 0.
15:53:54.172 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
15:53:54.172 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:53:54.199 INFO TrancheManager - Finding 4 tranches for 2786 variants
15:53:54.200 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:53:54.200 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
15:53:54.201 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-39314.8821 known=(0 @ 0.0000) novel=(2786 @ 3.2340) truthSites(2786 accessible, 2786 called), name=anonymous]
15:53:54.201 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:53:54.201 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
15:53:54.201 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-16.8308 known=(0 @ 0.0000) novel=(2783 @ 3.2295) truthSites(2786 accessible, 2783 called), name=anonymous]
15:53:54.201 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:53:54.202 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
15:53:54.202 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=1239951.3360 known=(0 @ 0.0000) novel=(2758 @ 3.2496) truthSites(2786 accessible, 2758 called), name=anonymous]
15:53:54.202 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:53:54.202 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
15:53:54.202 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=2091223.5520 known=(0 @ 0.0000) novel=(2507 @ 3.2205) truthSites(2786 accessible, 2507 called), name=anonymous]
15:53:54.203 INFO VariantRecalibrator - Writing out recalibration table...
15:53:54.257 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:53:54 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=629145600
15:53:54.259 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 3:53:57 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=828375040
[May 19, 2025 at 3:54:00 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=958398464
15:54:00.530 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:00.530 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:54:00.530 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:54:00.530 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:54:00.530 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:54:00.531 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:54:00 PM UTC
15:54:00.531 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:00.531 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:00.531 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:54:00.531 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:54:00.531 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:54:00.531 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:54:00.531 INFO VariantRecalibrator - Deflater: IntelDeflater
15:54:00.531 INFO VariantRecalibrator - Inflater: IntelInflater
15:54:00.531 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:54:00.531 INFO VariantRecalibrator - Requester pays: disabled
15:54:00.532 INFO VariantRecalibrator - Initializing engine
15:54:00.533 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
15:54:00.545 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
15:54:00.585 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
15:54:00.601 INFO VariantRecalibrator - Done initializing engine
15:54:00.602 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
15:54:00.620 INFO ProgressMeter - Starting traversal
15:54:00.620 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:54:00.701 INFO ProgressMeter - chr1:6212018 0.0 2791 2067407.4
15:54:00.701 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
15:54:00.701 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
15:54:00.702 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
15:54:00.702 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
15:54:00.702 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
15:54:00.703 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
15:54:00.703 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
15:54:00.703 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:00.754 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:00.771 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.16919
15:54:00.789 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.14268
15:54:00.806 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.19617
15:54:00.824 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.09047
15:54:00.841 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.05235
15:54:00.858 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04028
15:54:00.876 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02103
15:54:00.893 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01461
15:54:00.911 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01136
15:54:00.928 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00583
15:54:00.946 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00291
15:54:00.956 INFO VariantRecalibratorEngine - Convergence after 58 iterations!
15:54:00.958 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:54:00.966 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
15:54:00.972 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:54:00 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=958398464
15:54:00.974 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 3:54:01 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=958398464
[May 19, 2025 at 3:54:01 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=958398464
[May 19, 2025 at 3:54:02 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=958398464
[May 19, 2025 at 3:54:03 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=958398464
15:54:03.789 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:03.790 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:54:03.790 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:54:03.790 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:54:03.790 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:54:03.790 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:54:03 PM UTC
15:54:03.790 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:03.790 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:03.790 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:54:03.791 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:54:03.791 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:54:03.791 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:54:03.791 INFO VariantRecalibrator - Deflater: IntelDeflater
15:54:03.791 INFO VariantRecalibrator - Inflater: IntelInflater
15:54:03.791 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:54:03.791 INFO VariantRecalibrator - Requester pays: disabled
15:54:03.791 INFO VariantRecalibrator - Initializing engine
15:54:03.792 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
15:54:03.795 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
15:54:03.797 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
15:54:03.799 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
15:54:03.802 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
15:54:03.804 INFO VariantRecalibrator - Done initializing engine
15:54:03.806 WARN VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
15:54:03.806 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
15:54:03.806 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
15:54:03.806 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
15:54:03.807 INFO ProgressMeter - Starting traversal
15:54:03.807 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:54:04.783 INFO ProgressMeter - 20:9944766 0.0 131821 8103750.0
15:54:04.783 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
15:54:04.786 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
15:54:04.791 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
15:54:04.798 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
15:54:04.833 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:54:04.834 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:54:04.835 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:05.121 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:05.244 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
15:54:05.364 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
15:54:05.488 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
15:54:05.601 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
15:54:05.721 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
15:54:05.841 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
15:54:05.959 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
15:54:06.086 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
15:54:06.180 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
15:54:06.273 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
15:54:06.348 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
15:54:06.355 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:54:06.422 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
15:54:06.422 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:06.424 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:06.424 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
15:54:06.426 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:54:06.608 INFO TrancheManager - Finding 4 tranches for 131821 variants
15:54:06.648 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:54:06.659 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
15:54:06.659 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-240.7209 known=(59500 @ 2.2991) novel=(72321 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
15:54:06.659 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:54:06.671 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
15:54:06.671 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-3.1318 known=(59151 @ 2.3066) novel=(71923 @ 2.2295) truthSites(18665 accessible, 18646 called), name=anonymous]
15:54:06.671 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:54:06.684 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
15:54:06.685 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=2.2535 known=(57628 @ 2.3617) novel=(68589 @ 2.2769) truthSites(18665 accessible, 18478 called), name=anonymous]
15:54:06.685 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:54:06.698 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
15:54:06.699 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=7.6928 known=(45852 @ 2.4660) novel=(22477 @ 2.4146) truthSites(18665 accessible, 16798 called), name=anonymous]
15:54:06.699 INFO VariantRecalibrator - Writing out recalibration table...
15:54:07.022 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:54:07 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=958398464
15:54:07.060 INFO gatk - Initializing VQSR tests/resetting random number generator
15:54:07.071 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:07.071 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:54:07.071 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:54:07.071 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:54:07.071 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:54:07.071 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:54:07 PM UTC
15:54:07.071 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:07.071 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:07.072 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:54:07.072 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:54:07.072 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:54:07.072 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:54:07.072 INFO VariantRecalibrator - Deflater: IntelDeflater
15:54:07.072 INFO VariantRecalibrator - Inflater: IntelInflater
15:54:07.072 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:54:07.072 INFO VariantRecalibrator - Requester pays: disabled
15:54:07.072 INFO VariantRecalibrator - Initializing engine
15:54:07.073 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
15:54:07.076 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
15:54:07.077 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
15:54:07.079 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
15:54:07.081 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
15:54:07.082 INFO VariantRecalibrator - Done initializing engine
15:54:07.083 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
15:54:07.083 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
15:54:07.083 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
15:54:07.084 INFO ProgressMeter - Starting traversal
15:54:07.084 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:54:08.050 INFO ProgressMeter - 20:9944766 0.0 131821 8187639.8
15:54:08.050 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
15:54:08.053 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
15:54:08.059 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
15:54:08.065 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
15:54:08.093 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:54:08.095 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:54:08.095 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:08.396 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:08.521 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
15:54:08.625 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
15:54:08.718 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
15:54:08.808 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
15:54:08.899 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
15:54:08.989 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
15:54:09.082 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
15:54:09.176 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
15:54:09.268 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
15:54:09.370 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
15:54:09.445 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
15:54:09.452 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:54:09.519 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
15:54:09.519 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:09.520 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:09.521 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
15:54:09.523 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:54:09.703 INFO TrancheManager - Finding 4 tranches for 131821 variants
15:54:09.741 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:54:09.753 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
15:54:09.754 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-240.7209 known=(59500 @ 2.2991) novel=(72321 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
15:54:09.754 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:54:09.768 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
15:54:09.768 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-3.1318 known=(59151 @ 2.3066) novel=(71923 @ 2.2295) truthSites(18665 accessible, 18646 called), name=anonymous]
15:54:09.768 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:54:09.783 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
15:54:09.783 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=2.2535 known=(57628 @ 2.3617) novel=(68589 @ 2.2769) truthSites(18665 accessible, 18478 called), name=anonymous]
15:54:09.783 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:54:09.796 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
15:54:09.797 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=7.6928 known=(45852 @ 2.4660) novel=(22477 @ 2.4146) truthSites(18665 accessible, 16798 called), name=anonymous]
15:54:09.797 INFO VariantRecalibrator - Writing out recalibration table...
15:54:10.112 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:54:10 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=958398464
15:54:10.135 INFO gatk - Initializing VQSR tests/resetting random number generator
15:54:10.145 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:10.145 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:54:10.145 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:54:10.145 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:54:10.145 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:54:10.145 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:54:10 PM UTC
15:54:10.145 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:10.145 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:10.146 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:54:10.146 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:54:10.146 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:54:10.146 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:54:10.146 INFO VariantRecalibrator - Deflater: IntelDeflater
15:54:10.146 INFO VariantRecalibrator - Inflater: IntelInflater
15:54:10.146 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:54:10.146 INFO VariantRecalibrator - Requester pays: disabled
15:54:10.146 INFO VariantRecalibrator - Initializing engine
15:54:10.147 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
15:54:10.159 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
15:54:10.200 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
15:54:10.215 INFO VariantRecalibrator - Done initializing engine
15:54:10.216 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
15:54:10.227 INFO ProgressMeter - Starting traversal
15:54:10.227 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:54:10.275 INFO ProgressMeter - chr1:6212018 0.0 2791 3488750.0
15:54:10.276 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
15:54:10.276 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
15:54:10.276 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
15:54:10.276 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
15:54:10.276 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
15:54:10.277 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
15:54:10.277 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
15:54:10.277 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:10.310 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:10.327 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
15:54:10.344 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
15:54:10.361 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
15:54:10.379 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
15:54:10.396 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
15:54:10.413 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
15:54:10.430 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
15:54:10.448 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
15:54:10.465 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
15:54:10.482 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
15:54:10.499 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
15:54:10.517 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
15:54:10.517 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
15:54:10.518 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:54:10.527 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
15:54:10.527 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:10.527 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:10.528 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
15:54:10.528 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:54:10.536 INFO TrancheManager - Finding 4 tranches for 2786 variants
15:54:10.536 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:54:10.536 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
15:54:10.536 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-39326.4087 known=(0 @ 0.0000) novel=(2786 @ 3.2340) truthSites(2786 accessible, 2786 called), name=anonymous]
15:54:10.536 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:54:10.537 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
15:54:10.537 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-12.9282 known=(0 @ 0.0000) novel=(2783 @ 3.2295) truthSites(2786 accessible, 2783 called), name=anonymous]
15:54:10.537 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:54:10.537 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
15:54:10.537 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=626.3145 known=(0 @ 0.0000) novel=(2758 @ 3.2562) truthSites(2786 accessible, 2758 called), name=anonymous]
15:54:10.537 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:54:10.537 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
15:54:10.538 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=935.3268 known=(0 @ 0.0000) novel=(2507 @ 3.2134) truthSites(2786 accessible, 2507 called), name=anonymous]
15:54:10.538 INFO VariantRecalibrator - Writing out recalibration table...
15:54:10.552 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:54:10 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=958398464
15:54:10.556 INFO gatk - Initializing VQSR tests/resetting random number generator
15:54:10.565 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:10.565 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:54:10.565 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:54:10.565 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:54:10.565 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:54:10.565 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:54:10 PM UTC
15:54:10.565 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:10.565 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:10.565 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:54:10.565 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:54:10.565 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:54:10.566 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:54:10.566 INFO VariantRecalibrator - Deflater: IntelDeflater
15:54:10.566 INFO VariantRecalibrator - Inflater: IntelInflater
15:54:10.566 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:54:10.566 INFO VariantRecalibrator - Requester pays: disabled
15:54:10.566 INFO VariantRecalibrator - Initializing engine
15:54:10.567 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
15:54:10.569 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
15:54:10.571 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
15:54:10.573 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
15:54:10.575 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
15:54:10.576 INFO VariantRecalibrator - Done initializing engine
15:54:10.576 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
15:54:10.576 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
15:54:10.576 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
15:54:10.577 INFO ProgressMeter - Starting traversal
15:54:10.577 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:54:11.550 INFO ProgressMeter - 20:9944766 0.0 131821 8128735.9
15:54:11.550 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
15:54:11.553 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
15:54:11.557 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
15:54:11.561 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
15:54:11.584 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:54:11.586 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:54:11.586 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:11.874 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:11.988 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
15:54:12.102 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
15:54:12.220 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
15:54:12.344 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
15:54:12.470 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
15:54:12.596 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
15:54:12.730 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
15:54:12.824 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
15:54:12.918 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
15:54:13.011 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
15:54:13.086 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
15:54:13.094 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:54:13.165 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
15:54:13.165 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:13.167 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:13.167 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
15:54:13.169 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:54:13.354 INFO TrancheManager - Finding 12 tranches for 131821 variants
15:54:13.396 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:54:13.407 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
15:54:13.407 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-240.7209 known=(59500 @ 2.2991) novel=(72321 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
15:54:13.407 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
15:54:13.417 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001
15:54:13.418 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.95 minVQSLod=-6.6729 known=(59316 @ 2.3020) novel=(72124 @ 2.2259) truthSites(18665 accessible, 18655 called), name=anonymous]
15:54:13.418 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:54:13.429 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
15:54:13.429 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-3.1318 known=(59151 @ 2.3066) novel=(71923 @ 2.2295) truthSites(18665 accessible, 18646 called), name=anonymous]
15:54:13.429 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
15:54:13.441 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002
15:54:13.441 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.80 minVQSLod=-1.1986 known=(58885 @ 2.3181) novel=(71456 @ 2.2416) truthSites(18665 accessible, 18627 called), name=anonymous]
15:54:13.441 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
15:54:13.453 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004
15:54:13.453 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.60 minVQSLod=0.1656 known=(58528 @ 2.3328) novel=(70916 @ 2.2530) truthSites(18665 accessible, 18590 called), name=anonymous]
15:54:13.453 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
15:54:13.465 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005
15:54:13.465 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.50 minVQSLod=0.9426 known=(58256 @ 2.3427) novel=(70523 @ 2.2598) truthSites(18665 accessible, 18571 called), name=anonymous]
15:54:13.465 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
15:54:13.479 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006
15:54:13.479 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.40 minVQSLod=1.3251 known=(58072 @ 2.3504) novel=(70172 @ 2.2640) truthSites(18665 accessible, 18553 called), name=anonymous]
15:54:13.479 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
15:54:13.490 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007
15:54:13.490 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.30 minVQSLod=1.5909 known=(57947 @ 2.3539) novel=(69870 @ 2.2668) truthSites(18665 accessible, 18534 called), name=anonymous]
15:54:13.490 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:54:13.500 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
15:54:13.500 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=2.2535 known=(57628 @ 2.3617) novel=(68589 @ 2.2769) truthSites(18665 accessible, 18478 called), name=anonymous]
15:54:13.500 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
15:54:13.510 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020
15:54:13.510 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=98.00 minVQSLod=3.7431 known=(56497 @ 2.3862) novel=(64651 @ 2.3078) truthSites(18665 accessible, 18291 called), name=anonymous]
15:54:13.510 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
15:54:13.521 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030
15:54:13.521 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=97.00 minVQSLod=4.6404 known=(55330 @ 2.4003) novel=(59506 @ 2.3526) truthSites(18665 accessible, 18105 called), name=anonymous]
15:54:13.521 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:54:13.531 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
15:54:13.531 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=7.6928 known=(45852 @ 2.4660) novel=(22477 @ 2.4146) truthSites(18665 accessible, 16798 called), name=anonymous]
15:54:13.531 INFO VariantRecalibrator - Writing out recalibration table...
15:54:13.848 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:54:13 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=958398464
15:54:13.871 INFO gatk - Initializing VQSR tests/resetting random number generator
15:54:13.880 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:13.880 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:54:13.880 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:54:13.880 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:54:13.880 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:54:13.880 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:54:13 PM UTC
15:54:13.880 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:13.881 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:13.881 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:54:13.881 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:54:13.881 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:54:13.881 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:54:13.881 INFO VariantRecalibrator - Deflater: IntelDeflater
15:54:13.881 INFO VariantRecalibrator - Inflater: IntelInflater
15:54:13.881 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:54:13.881 INFO VariantRecalibrator - Requester pays: disabled
15:54:13.881 INFO VariantRecalibrator - Initializing engine
15:54:13.882 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
15:54:13.893 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
15:54:13.929 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
15:54:13.945 INFO VariantRecalibrator - Done initializing engine
15:54:13.945 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
15:54:13.957 INFO ProgressMeter - Starting traversal
15:54:13.957 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:54:14.002 INFO ProgressMeter - chr1:6212018 0.0 2791 3721333.3
15:54:14.002 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
15:54:14.003 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
15:54:14.003 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
15:54:14.003 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
15:54:14.003 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
15:54:14.004 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
15:54:14.004 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
15:54:14.004 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:14.037 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:14.055 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
15:54:14.072 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
15:54:14.089 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
15:54:14.107 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
15:54:14.124 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
15:54:14.141 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
15:54:14.158 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
15:54:14.176 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
15:54:14.193 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
15:54:14.210 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
15:54:14.228 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
15:54:14.245 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
15:54:14.245 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
15:54:14.247 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:54:14.255 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
15:54:14.256 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:14.256 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:14.256 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
15:54:14.256 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
15:54:14.265 INFO TrancheManager - Finding 12 tranches for 2786 variants
15:54:14.265 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:54:14.266 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
15:54:14.266 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-39326.4087 known=(0 @ 0.0000) novel=(2786 @ 3.2340) truthSites(2786 accessible, 2786 called), name=anonymous]
15:54:14.266 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
15:54:14.266 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001
15:54:14.266 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.95 minVQSLod=-22753.7269 known=(0 @ 0.0000) novel=(2784 @ 3.2310) truthSites(2786 accessible, 2784 called), name=anonymous]
15:54:14.266 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:54:14.266 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
15:54:14.266 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-12.9282 known=(0 @ 0.0000) novel=(2783 @ 3.2295) truthSites(2786 accessible, 2783 called), name=anonymous]
15:54:14.266 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
15:54:14.267 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002
15:54:14.267 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.80 minVQSLod=-5.7548 known=(0 @ 0.0000) novel=(2780 @ 3.2314) truthSites(2786 accessible, 2780 called), name=anonymous]
15:54:14.267 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
15:54:14.267 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004
15:54:14.267 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.60 minVQSLod=250.6941 known=(0 @ 0.0000) novel=(2774 @ 3.2481) truthSites(2786 accessible, 2774 called), name=anonymous]
15:54:14.267 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
15:54:14.267 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005
15:54:14.267 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.50 minVQSLod=342.2903 known=(0 @ 0.0000) novel=(2772 @ 3.2515) truthSites(2786 accessible, 2772 called), name=anonymous]
15:54:14.267 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
15:54:14.267 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006
15:54:14.267 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.40 minVQSLod=511.3402 known=(0 @ 0.0000) novel=(2769 @ 3.2469) truthSites(2786 accessible, 2769 called), name=anonymous]
15:54:14.268 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
15:54:14.268 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007
15:54:14.268 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.30 minVQSLod=573.6691 known=(0 @ 0.0000) novel=(2766 @ 3.2423) truthSites(2786 accessible, 2766 called), name=anonymous]
15:54:14.268 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:54:14.268 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
15:54:14.268 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=626.3145 known=(0 @ 0.0000) novel=(2758 @ 3.2562) truthSites(2786 accessible, 2758 called), name=anonymous]
15:54:14.268 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
15:54:14.268 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020
15:54:14.268 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=98.00 minVQSLod=710.0883 known=(0 @ 0.0000) novel=(2730 @ 3.2523) truthSites(2786 accessible, 2730 called), name=anonymous]
15:54:14.269 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
15:54:14.269 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030
15:54:14.269 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=97.00 minVQSLod=758.5107 known=(0 @ 0.0000) novel=(2702 @ 3.2484) truthSites(2786 accessible, 2702 called), name=anonymous]
15:54:14.269 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:54:14.269 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
15:54:14.269 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=935.3268 known=(0 @ 0.0000) novel=(2507 @ 3.2134) truthSites(2786 accessible, 2507 called), name=anonymous]
15:54:14.270 INFO VariantRecalibrator - Writing out recalibration table...
15:54:14.283 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:54:14 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=958398464
15:54:14.286 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 3:54:16 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=958398464
15:54:16.800 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:16.800 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:54:16.800 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:54:16.800 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:54:16.800 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:54:16.800 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:54:16 PM UTC
15:54:16.800 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:16.800 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:16.800 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:54:16.800 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:54:16.800 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:54:16.800 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:54:16.800 INFO VariantRecalibrator - Deflater: IntelDeflater
15:54:16.800 INFO VariantRecalibrator - Inflater: IntelInflater
15:54:16.800 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:54:16.800 INFO VariantRecalibrator - Requester pays: disabled
15:54:16.800 INFO VariantRecalibrator - Initializing engine
15:54:16.802 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
15:54:16.804 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
15:54:16.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
15:54:16.807 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
15:54:16.809 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
15:54:16.824 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
15:54:16.825 INFO VariantRecalibrator - Done initializing engine
15:54:16.825 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
15:54:16.825 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
15:54:16.825 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
15:54:16.827 INFO ProgressMeter - Starting traversal
15:54:16.828 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:54:17.843 INFO ProgressMeter - 20:9938789 0.0 134919 7975507.4
15:54:17.843 INFO ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
15:54:17.846 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
15:54:17.851 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
15:54:17.857 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
15:54:17.884 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:54:17.886 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:54:17.886 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:18.118 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:18.205 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.13181
15:54:18.303 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.46782
15:54:18.406 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 9.04961
15:54:18.492 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.04477
15:54:18.563 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01711
15:54:18.634 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.02053
15:54:18.704 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.01194
15:54:18.776 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01038
15:54:18.847 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.06192
15:54:18.918 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01281
15:54:18.991 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00457
15:54:19.020 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
15:54:19.025 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
15:54:19.114 INFO VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
15:54:19.114 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:19.116 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:19.118 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.05287
15:54:19.119 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.02030
15:54:19.120 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.00986
15:54:19.121 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.00749
15:54:19.123 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.00850
15:54:19.124 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01430
15:54:19.125 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02541
15:54:19.127 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.02173
15:54:19.128 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01024
15:54:19.129 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00479
15:54:19.130 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00245
15:54:19.131 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
15:54:19.133 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
15:54:19.313 INFO TrancheManager - Finding 4 tranches for 134603 variants
15:54:19.350 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
15:54:19.359 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
15:54:19.359 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=100.00 minVQSLod=-246.6082 known=(61809 @ 2.2991) novel=(72794 @ 2.2239) truthSites(18665 accessible, 18665 called), name=anonymous]
15:54:19.359 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
15:54:19.370 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001
15:54:19.370 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-4.2626 known=(61478 @ 2.3089) novel=(72476 @ 2.2282) truthSites(18665 accessible, 18646 called), name=anonymous]
15:54:19.370 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
15:54:19.381 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010
15:54:19.381 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.00 minVQSLod=0.6000 known=(59416 @ 2.3515) novel=(67263 @ 2.2813) truthSites(18665 accessible, 18478 called), name=anonymous]
15:54:19.381 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
15:54:19.391 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100
15:54:19.391 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=90.00 minVQSLod=4.4668 known=(48943 @ 2.4389) novel=(33028 @ 2.3795) truthSites(18665 accessible, 16798 called), name=anonymous]
15:54:19.391 INFO VariantRecalibrator - Writing out recalibration table...
15:54:19.704 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:54:19 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=958398464
15:54:19.705 INFO gatk - Initializing VQSR tests/resetting random number generator
15:54:19.713 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:19.713 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
15:54:19.713 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
15:54:19.713 INFO VariantRecalibrator - Executing as runner@pkrvmf6wy0o8zjz on Linux v6.11.0-1014-azure amd64
15:54:19.713 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
15:54:19.713 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 3:54:19 PM UTC
15:54:19.713 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:19.713 INFO VariantRecalibrator - ------------------------------------------------------------
15:54:19.713 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
15:54:19.714 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
15:54:19.714 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
15:54:19.714 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
15:54:19.714 INFO VariantRecalibrator - Deflater: IntelDeflater
15:54:19.714 INFO VariantRecalibrator - Inflater: IntelInflater
15:54:19.714 INFO VariantRecalibrator - GCS max retries/reopens: 20
15:54:19.714 INFO VariantRecalibrator - Requester pays: disabled
15:54:19.714 INFO VariantRecalibrator - Initializing engine
15:54:19.715 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
15:54:19.717 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
15:54:19.718 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
15:54:19.719 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
15:54:19.721 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
15:54:19.722 INFO VariantRecalibrator - Done initializing engine
15:54:19.722 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
15:54:19.722 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
15:54:19.722 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
15:54:19.723 INFO ProgressMeter - Starting traversal
15:54:19.723 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
15:54:20.691 INFO ProgressMeter - 20:9944766 0.0 131821 8170723.1
15:54:20.691 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
15:54:20.693 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
15:54:20.698 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
15:54:20.702 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
15:54:20.726 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
15:54:20.728 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
15:54:20.728 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:21.025 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:21.154 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
15:54:21.279 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
15:54:21.427 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
15:54:21.560 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
15:54:21.689 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
15:54:21.822 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
15:54:21.918 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
15:54:22.013 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
15:54:22.109 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
15:54:22.213 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
15:54:22.293 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
15:54:22.301 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:54:22.379 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
15:54:22.379 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
15:54:22.381 INFO VariantRecalibratorEngine - Finished iteration 0.
15:54:22.381 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
15:54:22.383 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
15:54:22.563 INFO TrancheManager - Finding 12 tranches for 131821 variants
15:54:22.601 INFO TrancheManager - VQSLODTranche threshold 10.00 => selection metric threshold 0.900
15:54:22.620 INFO TrancheManager - Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262
15:54:22.621 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
15:54:22.621 INFO TrancheManager - VQSLODTranche threshold 8.00 => selection metric threshold 0.920
15:54:22.635 INFO TrancheManager - Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114
15:54:22.635 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
15:54:22.635 INFO TrancheManager - VQSLODTranche threshold 6.00 => selection metric threshold 0.940
15:54:22.649 INFO TrancheManager - Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052
15:54:22.650 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
15:54:22.650 INFO TrancheManager - VQSLODTranche threshold 4.00 => selection metric threshold 0.960
15:54:22.663 INFO TrancheManager - Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023
15:54:22.664 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
15:54:22.664 INFO TrancheManager - VQSLODTranche threshold 2.00 => selection metric threshold 0.980
15:54:22.676 INFO TrancheManager - Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009
15:54:22.677 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
15:54:22.677 INFO TrancheManager - VQSLODTranche threshold 0.00 => selection metric threshold 1.000
15:54:22.690 INFO TrancheManager - Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004
15:54:22.690 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
15:54:22.690 INFO TrancheManager - VQSLODTranche threshold -2.00 => selection metric threshold 1.020
15:54:22.703 INFO TrancheManager - Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001
15:54:22.703 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
15:54:22.703 INFO TrancheManager - VQSLODTranche threshold -4.00 => selection metric threshold 1.040
15:54:22.715 INFO TrancheManager - Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001
15:54:22.715 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
15:54:22.715 INFO TrancheManager - VQSLODTranche threshold -6.00 => selection metric threshold 1.060
15:54:22.727 INFO TrancheManager - Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001
15:54:22.728 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
15:54:22.728 INFO TrancheManager - VQSLODTranche threshold -8.00 => selection metric threshold 1.080
15:54:22.740 INFO TrancheManager - Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000
15:54:22.740 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
15:54:22.740 INFO TrancheManager - VQSLODTranche threshold -10.00 => selection metric threshold 1.100
15:54:22.752 INFO TrancheManager - Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000
15:54:22.752 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
15:54:22.752 INFO TrancheManager - VQSLODTranche threshold -12.00 => selection metric threshold 1.120
15:54:22.766 INFO TrancheManager - Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000
15:54:22.766 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
15:54:22.767 INFO VariantRecalibrator - Writing out recalibration table...
15:54:23.083 INFO VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
15:54:23.087 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 3:54:23 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=958398464
[May 19, 2025 at 3:55:34 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1308622848